[PATCH bpf-next 0/6] BPF verifier rotating log

[PATCH bpf-next 0/6] BPF verifier rotating log

[Andrii Nakryiko]

This patch set changes BPF verifier log behavior to behave as a rotating log,
by default. If user-supplied log buffer is big enough to contain entire
verifier log output, there is no effective difference. But where previously
user supplied too small log buffer and would get -ENOSPC error result and the
beginning part of the verifier log, now there will be no error and user will
get ending part of verifier log filling up user-supplied log buffer.  Which
is, in absolute majority of cases, is exactly what's useful, relevant, and
what users want and need, as the ending of the verifier log is containing
details of verifier failure and relevant state that got us to that failure. So
this rotating mode is made default, but for some niche advanced debugging
scenarios it's possible to request old behavior by specifying additional
BPF_LOG_FIXED (8) flag.

This patch set adjusts libbpf to allow specifying flags beyond 1 | 2 | 4. We
also add --log-size and --log-fixed options to veristat to be able to both
test this functionality manually, but also to be used in various debugging
scenarios. We also add selftests that tries many variants of log buffer size
to stress-test correctness of internal verifier log bookkeeping code.

Andrii Nakryiko (6):
  bpf: split off basic BPF verifier log into separate file
  bpf: remove minimum size restrictions on verifier log buffer
  bpf: switch BPF verifier log to be a rotating log by default
  libbpf: don't enfore verifier log levels on libbpf side
  selftests/bpf: add more veristat control over verifier log options
  selftests/bpf: add fixed vs rotating verifier log tests

 include/linux/bpf_verifier.h                  |  47 ++--
 kernel/bpf/Makefile                           |   3 +-
 kernel/bpf/log.c                              | 251 ++++++++++++++++++
 kernel/bpf/verifier.c                         |  86 +-----
 tools/lib/bpf/bpf.c                           |   2 -
 .../selftests/bpf/prog_tests/log_fixup.c      |   1 +
 .../selftests/bpf/prog_tests/verifier_log.c   |  89 +++++++
 tools/testing/selftests/bpf/veristat.c        |  42 ++-
 8 files changed, 416 insertions(+), 105 deletions(-)
 create mode 100644 kernel/bpf/log.c
 create mode 100644 tools/testing/selftests/bpf/prog_tests/verifier_log.c

-- 
2.34.1

[PATCH bpf-next 1/6] bpf: split off basic BPF verifier log into separate file

[Andrii Nakryiko]

kernel/bpf/verifier.c file is large and growing larger all the time. So
it's good to start splitting off more or less self-contained parts into
separate files to keep source code size (somewhat) somewhat under
control.

This patch is a one step in this direction, moving some of BPF verifier log
routines into a separate kernel/bpf/log.c. Right now it's most low-level
and isolated routines to append data to log, reset log to previous
position, etc. Eventually we could probably move verifier state
printing logic here as well, but this patch doesn't attempt to do that
yet.

Subsequent patches will add more logic to verifier log management, so
having basics in a separate file will make sure verifier.c doesn't grow
more with new changes.

Signed-off-by: Andrii Nakryiko <andrii@kernel.org>
---
 include/linux/bpf_verifier.h | 19 +++-----
 kernel/bpf/Makefile          |  3 +-
 kernel/bpf/log.c             | 85 ++++++++++++++++++++++++++++++++++++
 kernel/bpf/verifier.c        | 69 -----------------------------
 4 files changed, 94 insertions(+), 82 deletions(-)
 create mode 100644 kernel/bpf/log.c

diff --git a/include/linux/bpf_verifier.h b/include/linux/bpf_verifier.h
index 81d525d057c7..83dff25545ee 100644
--- a/include/linux/bpf_verifier.h
+++ b/include/linux/bpf_verifier.h
@@ -498,11 +498,6 @@ struct bpf_verifier_log {
 	u32 len_total;
 };
 
-static inline bool bpf_verifier_log_full(const struct bpf_verifier_log *log)
-{
-	return log->len_used >= log->len_total - 1;
-}
-
 #define BPF_LOG_LEVEL1	1
 #define BPF_LOG_LEVEL2	2
 #define BPF_LOG_STATS	4
@@ -512,6 +507,11 @@ static inline bool bpf_verifier_log_full(const struct bpf_verifier_log *log)
 #define BPF_LOG_MIN_ALIGNMENT 8U
 #define BPF_LOG_ALIGNMENT 40U
 
+static inline bool bpf_verifier_log_full(const struct bpf_verifier_log *log)
+{
+	return log->len_used >= log->len_total - 1;
+}
+
 static inline bool bpf_verifier_log_needed(const struct bpf_verifier_log *log)
 {
 	return log &&
@@ -519,13 +519,6 @@ static inline bool bpf_verifier_log_needed(const struct bpf_verifier_log *log)
 		 log->level == BPF_LOG_KERNEL);
 }
 
-static inline bool
-bpf_verifier_log_attr_valid(const struct bpf_verifier_log *log)
-{
-	return log->len_total >= 128 && log->len_total <= UINT_MAX >> 2 &&
-	       log->level && log->ubuf && !(log->level & ~BPF_LOG_MASK);
-}
-
 #define BPF_MAX_SUBPROGS 256
 
 struct bpf_subprog_info {
@@ -608,12 +601,14 @@ struct bpf_verifier_env {
 	char type_str_buf[TYPE_STR_BUF_LEN];
 };
 
+bool bpf_verifier_log_attr_valid(const struct bpf_verifier_log *log);
 __printf(2, 0) void bpf_verifier_vlog(struct bpf_verifier_log *log,
 				      const char *fmt, va_list args);
 __printf(2, 3) void bpf_verifier_log_write(struct bpf_verifier_env *env,
 					   const char *fmt, ...);
 __printf(2, 3) void bpf_log(struct bpf_verifier_log *log,
 			    const char *fmt, ...);
+void bpf_vlog_reset(struct bpf_verifier_log *log, u32 new_pos);
 
 static inline struct bpf_func_state *cur_func(struct bpf_verifier_env *env)
 {
diff --git a/kernel/bpf/Makefile b/kernel/bpf/Makefile
index 02242614dcc7..1d3892168d32 100644
--- a/kernel/bpf/Makefile
+++ b/kernel/bpf/Makefile
@@ -6,7 +6,8 @@ cflags-nogcse-$(CONFIG_X86)$(CONFIG_CC_IS_GCC) := -fno-gcse
 endif
 CFLAGS_core.o += $(call cc-disable-warning, override-init) $(cflags-nogcse-yy)
 
-obj-$(CONFIG_BPF_SYSCALL) += syscall.o verifier.o inode.o helpers.o tnum.o bpf_iter.o map_iter.o task_iter.o prog_iter.o link_iter.o
+obj-$(CONFIG_BPF_SYSCALL) += syscall.o verifier.o inode.o helpers.o tnum.o log.o
+obj-$(CONFIG_BPF_SYSCALL) += bpf_iter.o map_iter.o task_iter.o prog_iter.o link_iter.o
 obj-$(CONFIG_BPF_SYSCALL) += hashtab.o arraymap.o percpu_freelist.o bpf_lru_list.o lpm_trie.o map_in_map.o bloom_filter.o
 obj-$(CONFIG_BPF_SYSCALL) += local_storage.o queue_stack_maps.o ringbuf.o
 obj-$(CONFIG_BPF_SYSCALL) += bpf_local_storage.o bpf_task_storage.o
diff --git a/kernel/bpf/log.c b/kernel/bpf/log.c
new file mode 100644
index 000000000000..920061e38d2e
--- /dev/null
+++ b/kernel/bpf/log.c
@@ -0,0 +1,85 @@
+// SPDX-License-Identifier: GPL-2.0-only
+/* Copyright (c) 2011-2014 PLUMgrid, http://plumgrid.com
+ * Copyright (c) 2016 Facebook
+ * Copyright (c) 2018 Covalent IO, Inc. http://covalent.io
+ */
+#include <uapi/linux/btf.h>
+#include <linux/kernel.h>
+#include <linux/types.h>
+#include <linux/bpf.h>
+#include <linux/bpf_verifier.h>
+
+bool bpf_verifier_log_attr_valid(const struct bpf_verifier_log *log)
+{
+	return log->len_total >= 128 && log->len_total <= UINT_MAX >> 2 &&
+	       log->level && log->ubuf && !(log->level & ~BPF_LOG_MASK);
+}
+
+void bpf_verifier_vlog(struct bpf_verifier_log *log, const char *fmt,
+		       va_list args)
+{
+	unsigned int n;
+
+	n = vscnprintf(log->kbuf, BPF_VERIFIER_TMP_LOG_SIZE, fmt, args);
+
+	WARN_ONCE(n >= BPF_VERIFIER_TMP_LOG_SIZE - 1,
+		  "verifier log line truncated - local buffer too short\n");
+
+	if (log->level == BPF_LOG_KERNEL) {
+		bool newline = n > 0 && log->kbuf[n - 1] == '\n';
+
+		pr_err("BPF: %s%s", log->kbuf, newline ? "" : "\n");
+		return;
+	}
+
+	n = min(log->len_total - log->len_used - 1, n);
+	log->kbuf[n] = '\0';
+	if (!copy_to_user(log->ubuf + log->len_used, log->kbuf, n + 1))
+		log->len_used += n;
+	else
+		log->ubuf = NULL;
+}
+
+void bpf_vlog_reset(struct bpf_verifier_log *log, u32 new_pos)
+{
+	char zero = 0;
+
+	if (!bpf_verifier_log_needed(log))
+		return;
+
+	log->len_used = new_pos;
+	if (put_user(zero, log->ubuf + new_pos))
+		log->ubuf = NULL;
+}
+
+/* log_level controls verbosity level of eBPF verifier.
+ * bpf_verifier_log_write() is used to dump the verification trace to the log,
+ * so the user can figure out what's wrong with the program
+ */
+__printf(2, 3) void bpf_verifier_log_write(struct bpf_verifier_env *env,
+					   const char *fmt, ...)
+{
+	va_list args;
+
+	if (!bpf_verifier_log_needed(&env->log))
+		return;
+
+	va_start(args, fmt);
+	bpf_verifier_vlog(&env->log, fmt, args);
+	va_end(args);
+}
+EXPORT_SYMBOL_GPL(bpf_verifier_log_write);
+
+__printf(2, 3) void bpf_log(struct bpf_verifier_log *log,
+			    const char *fmt, ...)
+{
+	va_list args;
+
+	if (!bpf_verifier_log_needed(log))
+		return;
+
+	va_start(args, fmt);
+	bpf_verifier_vlog(log, fmt, args);
+	va_end(args);
+}
+EXPORT_SYMBOL_GPL(bpf_log);
diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
index 60793f793ca6..203d6e644e44 100644
--- a/kernel/bpf/verifier.c
+++ b/kernel/bpf/verifier.c
@@ -335,61 +335,6 @@ find_linfo(const struct bpf_verifier_env *env, u32 insn_off)
 	return &linfo[i - 1];
 }
 
-void bpf_verifier_vlog(struct bpf_verifier_log *log, const char *fmt,
-		       va_list args)
-{
-	unsigned int n;
-
-	n = vscnprintf(log->kbuf, BPF_VERIFIER_TMP_LOG_SIZE, fmt, args);
-
-	WARN_ONCE(n >= BPF_VERIFIER_TMP_LOG_SIZE - 1,
-		  "verifier log line truncated - local buffer too short\n");
-
-	if (log->level == BPF_LOG_KERNEL) {
-		bool newline = n > 0 && log->kbuf[n - 1] == '\n';
-
-		pr_err("BPF: %s%s", log->kbuf, newline ? "" : "\n");
-		return;
-	}
-
-	n = min(log->len_total - log->len_used - 1, n);
-	log->kbuf[n] = '\0';
-	if (!copy_to_user(log->ubuf + log->len_used, log->kbuf, n + 1))
-		log->len_used += n;
-	else
-		log->ubuf = NULL;
-}
-
-static void bpf_vlog_reset(struct bpf_verifier_log *log, u32 new_pos)
-{
-	char zero = 0;
-
-	if (!bpf_verifier_log_needed(log))
-		return;
-
-	log->len_used = new_pos;
-	if (put_user(zero, log->ubuf + new_pos))
-		log->ubuf = NULL;
-}
-
-/* log_level controls verbosity level of eBPF verifier.
- * bpf_verifier_log_write() is used to dump the verification trace to the log,
- * so the user can figure out what's wrong with the program
- */
-__printf(2, 3) void bpf_verifier_log_write(struct bpf_verifier_env *env,
-					   const char *fmt, ...)
-{
-	va_list args;
-
-	if (!bpf_verifier_log_needed(&env->log))
-		return;
-
-	va_start(args, fmt);
-	bpf_verifier_vlog(&env->log, fmt, args);
-	va_end(args);
-}
-EXPORT_SYMBOL_GPL(bpf_verifier_log_write);
-
 __printf(2, 3) static void verbose(void *private_data, const char *fmt, ...)
 {
 	struct bpf_verifier_env *env = private_data;
@@ -403,20 +348,6 @@ __printf(2, 3) static void verbose(void *private_data, const char *fmt, ...)
 	va_end(args);
 }
 
-__printf(2, 3) void bpf_log(struct bpf_verifier_log *log,
-			    const char *fmt, ...)
-{
-	va_list args;
-
-	if (!bpf_verifier_log_needed(log))
-		return;
-
-	va_start(args, fmt);
-	bpf_verifier_vlog(log, fmt, args);
-	va_end(args);
-}
-EXPORT_SYMBOL_GPL(bpf_log);
-
 static const char *ltrim(const char *s)
 {
 	while (isspace(*s))
-- 
2.34.1

[PATCH bpf-next 2/6] bpf: remove minimum size restrictions on verifier log buffer

[Andrii Nakryiko]

It's not clear why we have 128 as minimum size, but it makes testing
harder and seems unnecessary, as we carefully handle truncation
scenarios and use proper snprintf variants. So remove this limitation
and just enfore positive length for log buffer.

Signed-off-by: Andrii Nakryiko <andrii@kernel.org>
---
 kernel/bpf/log.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/kernel/bpf/log.c b/kernel/bpf/log.c
index 920061e38d2e..1974891fc324 100644
--- a/kernel/bpf/log.c
+++ b/kernel/bpf/log.c
@@ -11,7 +11,7 @@
 
 bool bpf_verifier_log_attr_valid(const struct bpf_verifier_log *log)
 {
-	return log->len_total >= 128 && log->len_total <= UINT_MAX >> 2 &&
+	return log->len_total > 0 && log->len_total <= UINT_MAX >> 2 &&
 	       log->level && log->ubuf && !(log->level & ~BPF_LOG_MASK);
 }
 
-- 
2.34.1

[PATCH bpf-next 3/6] bpf: switch BPF verifier log to be a rotating log by default

[Andrii Nakryiko]

Currently, if user-supplied log buffer to collect BPF verifier log turns
out to be too small to contain full log, bpf() syscall return -ENOSPC,
fails BPF program verification/load, but preserves first N-1 bytes of
verifier log (where N is the size of user-supplied buffer).

This is problematic in a bunch of common scenarios, especially when
working with real-world BPF programs that tend to be pretty complex as
far as verification goes and require big log buffers. Typically, it's
when debugging tricky cases at log level 2 (verbose). Also, when BPF program
is successfully validated, log level 2 is the only way to actually see
verifier state progression and all the important details.

Even with log level 1, it's possible to get -ENOSPC even if the final
verifier log fits in log buffer, if there is a code path that's deep
enough to fill up entire log, even if normally it would be reset later
on (there is a logic to chop off successfully validated portions of BPF
verifier log).

In short, it's not always possible to pre-size log buffer. Also, in
practice, the end of the log most often is way more important than the
beginning.

This patch switches BPF verifier log behavior to effectively behave as
rotating log. That is, if user-supplied log buffer turns out to be too
short, instead of failing with -ENOSPC, verifier will keep overwriting
previously written log, effectively treating user's log buffer as a ring
buffer.

Importantly, though, to preserve good user experience and not require
every user-space application to adopt to this new behavior, before
exiting to user-space verifier will rotate log (in place) to make it
start at the very beginning of user buffer as a continuous
zero-terminated string. The contents will be a chopped off N-1 last
bytes of full verifier log, of course.

Given beginning of log is sometimes important as well, we add
BPF_LOG_FIXED (which equals 8) flag to force old behavior, which allows
tools like veristat to request first part of verifier log, if necessary.

On the implementation side, conceptually, it's all simple. We maintain
64-bit logical start and end positions. If we need to truncate the log,
start position will be adjusted accordingly to lag end position by
N bytes. We then use those logical positions to calculate their matching
actual positions in user buffer and handle wrap around the end of the
buffer properly. Finally, right before returning from bpf_check(), we
rotate user log buffer contents in-place as necessary, to make log
contents contiguous. See comments in relevant functions for details.

Signed-off-by: Andrii Nakryiko <andrii@kernel.org>
---
 include/linux/bpf_verifier.h                  |  32 ++-
 kernel/bpf/log.c                              | 182 +++++++++++++++++-
 kernel/bpf/verifier.c                         |  17 +-
 .../selftests/bpf/prog_tests/log_fixup.c      |   1 +
 4 files changed, 209 insertions(+), 23 deletions(-)

diff --git a/include/linux/bpf_verifier.h b/include/linux/bpf_verifier.h
index 83dff25545ee..cff11c99ed9a 100644
--- a/include/linux/bpf_verifier.h
+++ b/include/linux/bpf_verifier.h
@@ -491,25 +491,42 @@ struct bpf_insn_aux_data {
 #define BPF_VERIFIER_TMP_LOG_SIZE	1024
 
 struct bpf_verifier_log {
-	u32 level;
-	char kbuf[BPF_VERIFIER_TMP_LOG_SIZE];
+	/* Logical start and end positions of a "log window" of the verifier log.
+	 * start_pos == 0 means we haven't truncated anything.
+	 * Once truncation starts to happen, start_pos + len_total == end_pos,
+	 * except during log reset situations, in which (end_pos - start_pos)
+	 * might get smaller than len_total (see bpf_vlog_reset()).
+	 * Generally, (end_pos - start_pos) gives number of useful data in
+	 * user log buffer.
+	 */
+	u64 start_pos;
+	u64 end_pos;
 	char __user *ubuf;
-	u32 len_used;
+	u32 level;
 	u32 len_total;
+	char kbuf[BPF_VERIFIER_TMP_LOG_SIZE];
 };
 
 #define BPF_LOG_LEVEL1	1
 #define BPF_LOG_LEVEL2	2
 #define BPF_LOG_STATS	4
+#define BPF_LOG_FIXED	8
 #define BPF_LOG_LEVEL	(BPF_LOG_LEVEL1 | BPF_LOG_LEVEL2)
-#define BPF_LOG_MASK	(BPF_LOG_LEVEL | BPF_LOG_STATS)
+#define BPF_LOG_MASK	(BPF_LOG_LEVEL | BPF_LOG_STATS | BPF_LOG_FIXED)
 #define BPF_LOG_KERNEL	(BPF_LOG_MASK + 1) /* kernel internal flag */
 #define BPF_LOG_MIN_ALIGNMENT 8U
 #define BPF_LOG_ALIGNMENT 40U
 
+static inline u32 bpf_log_used(const struct bpf_verifier_log *log)
+{
+	return log->end_pos - log->start_pos;
+}
+
 static inline bool bpf_verifier_log_full(const struct bpf_verifier_log *log)
 {
-	return log->len_used >= log->len_total - 1;
+	if (log->level & BPF_LOG_FIXED)
+		return bpf_log_used(log) >= log->len_total - 1;
+	return false;
 }
 
 static inline bool bpf_verifier_log_needed(const struct bpf_verifier_log *log)
@@ -596,7 +613,7 @@ struct bpf_verifier_env {
 	u32 scratched_regs;
 	/* Same as scratched_regs but for stack slots */
 	u64 scratched_stack_slots;
-	u32 prev_log_len, prev_insn_print_len;
+	u64 prev_log_pos, prev_insn_print_pos;
 	/* buffer used in reg_type_str() to generate reg_type string */
 	char type_str_buf[TYPE_STR_BUF_LEN];
 };
@@ -608,7 +625,8 @@ __printf(2, 3) void bpf_verifier_log_write(struct bpf_verifier_env *env,
 					   const char *fmt, ...);
 __printf(2, 3) void bpf_log(struct bpf_verifier_log *log,
 			    const char *fmt, ...);
-void bpf_vlog_reset(struct bpf_verifier_log *log, u32 new_pos);
+void bpf_vlog_reset(struct bpf_verifier_log *log, u64 new_pos);
+void bpf_vlog_finalize(struct bpf_verifier_log *log);
 
 static inline struct bpf_func_state *cur_func(struct bpf_verifier_env *env)
 {
diff --git a/kernel/bpf/log.c b/kernel/bpf/log.c
index 1974891fc324..ec640828e84e 100644
--- a/kernel/bpf/log.c
+++ b/kernel/bpf/log.c
@@ -32,26 +32,192 @@ void bpf_verifier_vlog(struct bpf_verifier_log *log, const char *fmt,
 		return;
 	}
 
-	n = min(log->len_total - log->len_used - 1, n);
-	log->kbuf[n] = '\0';
-	if (!copy_to_user(log->ubuf + log->len_used, log->kbuf, n + 1))
-		log->len_used += n;
-	else
-		log->ubuf = NULL;
+	if (log->level & BPF_LOG_FIXED) {
+		n = min(log->len_total - bpf_log_used(log) - 1, n);
+		log->kbuf[n] = '\0';
+		n += 1;
+
+		if (copy_to_user(log->ubuf + log->end_pos, log->kbuf, n))
+			goto fail;
+
+		log->end_pos += n - 1; /* don't count terminating '\0' */
+	} else {
+		u64 new_end, new_start, cur_pos;
+		u32 buf_start, buf_end, new_n;
+
+		log->kbuf[n] = '\0';
+		n += 1;
+
+		new_end = log->end_pos + n;
+		if (new_end - log->start_pos >= log->len_total)
+			new_start = new_end - log->len_total;
+		else
+			new_start = log->start_pos;
+		new_n = min(n, log->len_total);
+		cur_pos = new_end - new_n;
+
+		buf_start = cur_pos % log->len_total;
+		buf_end = new_end % log->len_total;
+		/* new_end and buf_end are exclusive indices, so if buf_end is
+		 * exactly zero, then it actually points right to the end of
+		 * ubuf and there is no wrap around
+		 */
+		if (buf_end == 0)
+			buf_end = log->len_total;
+
+		/* if buf_start > buf_end, we wrapped around;
+		 * if buf_start == buf_end, then we fill ubuf completely; we
+		 * can't have buf_start == buf_end to mean that there is
+		 * nothing to write, because we always write at least
+		 * something, even if terminal '\0'
+		 */
+		if (buf_start < buf_end) {
+			/* message fits within contiguous chunk of ubuf */
+			if (copy_to_user(log->ubuf + buf_start,
+					 log->kbuf + n - new_n,
+					 buf_end - buf_start))
+				goto fail;
+		} else {
+			/* message wraps around the end of ubuf, copy in two chunks */
+			if (copy_to_user(log->ubuf + buf_start,
+					 log->kbuf + n - new_n,
+					 log->len_total - buf_start))
+				goto fail;
+			if (copy_to_user(log->ubuf,
+					 log->kbuf + n - buf_end,
+					 buf_end))
+				goto fail;
+		}
+
+		log->start_pos = new_start;
+		log->end_pos = new_end - 1; /* don't count terminating '\0' */
+	}
+
+	return;
+fail:
+	log->ubuf = NULL;
 }
 
-void bpf_vlog_reset(struct bpf_verifier_log *log, u32 new_pos)
+void bpf_vlog_reset(struct bpf_verifier_log *log, u64 new_pos)
 {
 	char zero = 0;
 
 	if (!bpf_verifier_log_needed(log))
 		return;
 
-	log->len_used = new_pos;
+	/* if position to which we reset is beyond current log window, then we
+	 * didn't preserve any useful content and should adjust adjust
+	 * start_pos to end up with an empty log (start_pos == end_pos)
+	 */
+	log->end_pos = new_pos;
+	if (log->end_pos < log->start_pos)
+		log->start_pos = log->end_pos;
+
 	if (put_user(zero, log->ubuf + new_pos))
 		log->ubuf = NULL;
 }
 
+static void bpf_vlog_reverse_kbuf(char *buf, int len)
+{
+	int i, j;
+
+	for (i = 0, j = len - 1; i < j; i++, j--)
+		swap(buf[i], buf[j]);
+}
+
+static int bpf_vlog_reverse_ubuf(struct bpf_verifier_log *log, int start, int end)
+{
+	/* we split log->kbuf into two equal parts for both ends of array */
+	int n = sizeof(log->kbuf) / 2, nn;
+	char *lbuf = log->kbuf, *rbuf = log->kbuf + n;
+
+	/* Read ubuf's section [start, end) two chunks at a time, from left
+	 * and right side; within each chunk, swap all the bytes; after that
+	 * reverse the order of lbuf and rbuf and write result back to ubuf.
+	 * This way we'll end up with swapped contents of specified
+	 * [start, end) ubuf segment.
+	 */
+	while (end - start > 1) {
+		nn = min(n, (end - start ) / 2);
+
+		if (copy_from_user(lbuf, log->ubuf + start, nn))
+			return -EFAULT;
+		if (copy_from_user(rbuf, log->ubuf + end - nn, nn))
+			return -EFAULT;
+
+		bpf_vlog_reverse_kbuf(lbuf, nn);
+		bpf_vlog_reverse_kbuf(rbuf, nn);
+
+		/* we write lbuf to the right end of ubuf, while rbuf to the
+		 * left one to end up with properly reversed overall ubuf
+		 */
+		if (copy_to_user(log->ubuf + start, rbuf, nn))
+			return -EFAULT;
+		if (copy_to_user(log->ubuf + end - nn, lbuf, nn))
+			return -EFAULT;
+
+		start += nn;
+		end -= nn;
+	}
+
+	return 0;
+}
+
+void bpf_vlog_finalize(struct bpf_verifier_log *log)
+{
+	u32 sublen;
+	int err;
+
+	if (!log || !log->level || !log->ubuf)
+		return;
+	if ((log->level & BPF_LOG_FIXED) || log->level == BPF_LOG_KERNEL)
+		return;
+
+	/* If we never truncated log, there is nothing to move around. */
+	if (log->start_pos == 0)
+		return;
+
+	/* Otherwise we need to rotate log contents to make it start from the
+	 * buffer beginning and be a continuous zero-terminated string. Note
+	 * that if log->start_pos != 0 then we definitely filled up entire log
+	 * buffer with no gaps, and we just need to shift buffer contents to
+	 * the left by (log->start_pos % log->len_total) bytes.
+	 *
+	 * Unfortunately, user buffer could be huge and we don't want to
+	 * allocate temporary kernel memory of the same size just to shift
+	 * contents in a straightforward fashion. Instead, we'll be clever and
+	 * do in-place array rotation. This is a leetcode-style problem, which
+	 * could be solved by three rotations.
+	 *
+	 * Let's say we have log buffer that has to be shifted left by 7 bytes
+	 * (spaces and vertical bar is just for demonstrative purposes):
+	 *   E F G H I J K | A B C D
+	 *
+	 * First, we reverse entire array:
+	 *   D C B A | K J I H G F E
+	 *
+	 * Then we rotate first 4 bytes (DCBA) and separately last 7 bytes
+	 * (KJIHGFE), resulting in a properly rotated array:
+	 *   A B C D | E F G H I J K
+	 *
+	 * We'll utilize log->kbuf to read user memory chunk by chunk, swap
+	 * bytes, and write them back. Doing it byte-by-byte would be
+	 * unnecessarily inefficient. Altogether we are going to read and
+	 * write each byte twice.
+	 */
+
+	/* length of the chopped off part that will be the beginning;
+	 * len(ABCD) in the example above
+	 */
+	sublen = log->len_total - (log->start_pos % log->len_total);
+
+	err = bpf_vlog_reverse_ubuf(log, 0, log->len_total);
+	err = err ?: bpf_vlog_reverse_ubuf(log, 0, sublen);
+	err = err ?: bpf_vlog_reverse_ubuf(log, sublen, log->len_total);
+	if (err)
+		log->ubuf = NULL;
+}
+
 /* log_level controls verbosity level of eBPF verifier.
  * bpf_verifier_log_write() is used to dump the verification trace to the log,
  * so the user can figure out what's wrong with the program
diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
index 203d6e644e44..f6d3d448e1b1 100644
--- a/kernel/bpf/verifier.c
+++ b/kernel/bpf/verifier.c
@@ -1435,10 +1435,10 @@ static inline u32 vlog_alignment(u32 pos)
 static void print_insn_state(struct bpf_verifier_env *env,
 			     const struct bpf_func_state *state)
 {
-	if (env->prev_log_len && env->prev_log_len == env->log.len_used) {
+	if (env->prev_log_pos && env->prev_log_pos == env->log.end_pos) {
 		/* remove new line character */
-		bpf_vlog_reset(&env->log, env->prev_log_len - 1);
-		verbose(env, "%*c;", vlog_alignment(env->prev_insn_print_len), ' ');
+		bpf_vlog_reset(&env->log, env->prev_log_pos - 1);
+		verbose(env, "%*c;", vlog_alignment(env->prev_insn_print_pos), ' ');
 	} else {
 		verbose(env, "%d:", env->insn_idx);
 	}
@@ -1746,7 +1746,7 @@ static struct bpf_verifier_state *push_stack(struct bpf_verifier_env *env,
 	elem->insn_idx = insn_idx;
 	elem->prev_insn_idx = prev_insn_idx;
 	elem->next = env->head;
-	elem->log_pos = env->log.len_used;
+	elem->log_pos = env->log.end_pos;
 	env->head = elem;
 	env->stack_size++;
 	err = copy_verifier_state(&elem->st, cur);
@@ -2282,7 +2282,7 @@ static struct bpf_verifier_state *push_async_cb(struct bpf_verifier_env *env,
 	elem->insn_idx = insn_idx;
 	elem->prev_insn_idx = prev_insn_idx;
 	elem->next = env->head;
-	elem->log_pos = env->log.len_used;
+	elem->log_pos = env->log.end_pos;
 	env->head = elem;
 	env->stack_size++;
 	if (env->stack_size > BPF_COMPLEXITY_LIMIT_JMP_SEQ) {
@@ -15563,11 +15563,11 @@ static int do_check(struct bpf_verifier_env *env)
 				print_insn_state(env, state->frame[state->curframe]);
 
 			verbose_linfo(env, env->insn_idx, "; ");
-			env->prev_log_len = env->log.len_used;
+			env->prev_log_pos = env->log.end_pos;
 			verbose(env, "%d: ", env->insn_idx);
 			print_bpf_insn(&cbs, insn, env->allow_ptr_leaks);
-			env->prev_insn_print_len = env->log.len_used - env->prev_log_len;
-			env->prev_log_len = env->log.len_used;
+			env->prev_insn_print_pos = env->log.end_pos - env->prev_log_pos;
+			env->prev_log_pos = env->log.end_pos;
 		}
 
 		if (bpf_prog_is_offloaded(env->prog->aux)) {
@@ -18780,6 +18780,7 @@ int bpf_check(struct bpf_prog **prog, union bpf_attr *attr, bpfptr_t uattr)
 	print_verification_stats(env);
 	env->prog->aux->verified_insns = env->insn_processed;
 
+	bpf_vlog_finalize(log);
 	if (log->level && bpf_verifier_log_full(log))
 		ret = -ENOSPC;
 	if (log->level && !log->ubuf) {
diff --git a/tools/testing/selftests/bpf/prog_tests/log_fixup.c b/tools/testing/selftests/bpf/prog_tests/log_fixup.c
index 239e1c5753b0..bc27170bdeb0 100644
--- a/tools/testing/selftests/bpf/prog_tests/log_fixup.c
+++ b/tools/testing/selftests/bpf/prog_tests/log_fixup.c
@@ -24,6 +24,7 @@ static void bad_core_relo(size_t log_buf_size, enum trunc_type trunc_type)
 	bpf_program__set_autoload(skel->progs.bad_relo, true);
 	memset(log_buf, 0, sizeof(log_buf));
 	bpf_program__set_log_buf(skel->progs.bad_relo, log_buf, log_buf_size ?: sizeof(log_buf));
+	bpf_program__set_log_level(skel->progs.bad_relo, 1 | 8); /* BPF_LOG_FIXED to force truncation */
 
 	err = test_log_fixup__load(skel);
 	if (!ASSERT_ERR(err, "load_fail"))
-- 
2.34.1

[PATCH bpf-next 4/6] libbpf: don't enfore verifier log levels on libbpf side

[Andrii Nakryiko]

This basically prevents any forward compatibility. And we either way
just return -EINVAL, which would otherwise be returned from bpf()
syscall anyways.

Signed-off-by: Andrii Nakryiko <andrii@kernel.org>
---
 tools/lib/bpf/bpf.c | 2 --
 1 file changed, 2 deletions(-)

diff --git a/tools/lib/bpf/bpf.c b/tools/lib/bpf/bpf.c
index e750b6f5fcc3..eb08a998b526 100644
--- a/tools/lib/bpf/bpf.c
+++ b/tools/lib/bpf/bpf.c
@@ -290,8 +290,6 @@ int bpf_prog_load(enum bpf_prog_type prog_type,
 
 	if (!!log_buf != !!log_size)
 		return libbpf_err(-EINVAL);
-	if (log_level > (4 | 2 | 1))
-		return libbpf_err(-EINVAL);
 	if (log_level && !log_buf)
 		return libbpf_err(-EINVAL);
 
-- 
2.34.1

[PATCH bpf-next 5/6] selftests/bpf: add more veristat control over verifier log options

[Andrii Nakryiko]

Add --log-size to be able to customize log buffer sent to bpf() syscall
for BPF program verification logging.

Add --log-fixed to enforce BPF_LOG_FIXED behavior for BPF verifier log.
This is useful in unlikely event that beginning of truncated verifier
log is more important than the end of it (which with rotating verifier
log behavior is the default now).

Signed-off-by: Andrii Nakryiko <andrii@kernel.org>
---
 tools/testing/selftests/bpf/veristat.c | 42 +++++++++++++++++++++-----
 1 file changed, 34 insertions(+), 8 deletions(-)

diff --git a/tools/testing/selftests/bpf/veristat.c b/tools/testing/selftests/bpf/veristat.c
index 83231456d3c5..3d24b6b96e75 100644
--- a/tools/testing/selftests/bpf/veristat.c
+++ b/tools/testing/selftests/bpf/veristat.c
@@ -136,11 +136,14 @@ static struct env {
 	int filename_cnt;
 	bool verbose;
 	bool quiet;
-	int log_level;
 	enum resfmt out_fmt;
 	bool comparison_mode;
 	bool replay_mode;
 
+	int log_level;
+	int log_size;
+	bool log_fixed;
+
 	struct verif_stats *prog_stats;
 	int prog_stat_cnt;
 
@@ -182,10 +185,17 @@ const char argp_program_doc[] =
 "USAGE: veristat <obj-file> [<obj-file>...]\n"
 "   OR: veristat -C <baseline.csv> <comparison.csv>\n";
 
+enum {
+	OPT_LOG_FIXED = 1000,
+	OPT_LOG_SIZE = 1001,
+};
+
 static const struct argp_option opts[] = {
 	{ NULL, 'h', NULL, OPTION_HIDDEN, "Show the full help" },
 	{ "verbose", 'v', NULL, 0, "Verbose mode" },
 	{ "log-level", 'l', "LEVEL", 0, "Verifier log level (default 0 for normal mode, 1 for verbose mode)" },
+	{ "log-fixed", OPT_LOG_FIXED, NULL, 0, "Disable verifier log rotation" },
+	{ "log-size", OPT_LOG_SIZE, "BYTES", 0, "Customize verifier log size (default to 16MB)" },
 	{ "quiet", 'q', NULL, 0, "Quiet mode" },
 	{ "emit", 'e', "SPEC", 0, "Specify stats to be emitted" },
 	{ "sort", 's', "SPEC", 0, "Specify sort order" },
@@ -243,6 +253,17 @@ static error_t parse_arg(int key, char *arg, struct argp_state *state)
 			argp_usage(state);
 		}
 		break;
+	case OPT_LOG_FIXED:
+		env.log_fixed = true;
+		break;
+	case OPT_LOG_SIZE:
+		errno = 0;
+		env.log_size = strtol(arg, NULL, 10);
+		if (errno) {
+			fprintf(stderr, "invalid log size: %s\n", arg);
+			argp_usage(state);
+		}
+		break;
 	case 'C':
 		env.comparison_mode = true;
 		break;
@@ -797,8 +818,8 @@ static void fixup_obj(struct bpf_object *obj)
 static int process_prog(const char *filename, struct bpf_object *obj, struct bpf_program *prog)
 {
 	const char *prog_name = bpf_program__name(prog);
-	size_t buf_sz = sizeof(verif_log_buf);
-	char *buf = verif_log_buf;
+	char *buf;
+	int buf_sz, log_level;
 	struct verif_stats *stats;
 	int err = 0;
 	void *tmp;
@@ -816,18 +837,23 @@ static int process_prog(const char *filename, struct bpf_object *obj, struct bpf
 	memset(stats, 0, sizeof(*stats));
 
 	if (env.verbose) {
-		buf_sz = 16 * 1024 * 1024;
+		buf_sz = env.log_size ? env.log_size : 16 * 1024 * 1024;
 		buf = malloc(buf_sz);
 		if (!buf)
 			return -ENOMEM;
-		bpf_program__set_log_buf(prog, buf, buf_sz);
-		bpf_program__set_log_level(prog, env.log_level | 4); /* stats + log */
+		/* ensure we always request stats */
+		log_level = env.log_level | 4 | (env.log_fixed ? 8 : 0);
 	} else {
-		bpf_program__set_log_buf(prog, buf, buf_sz);
-		bpf_program__set_log_level(prog, 4); /* only verifier stats */
+		buf = verif_log_buf;
+		buf_sz = sizeof(verif_log_buf);
+		/* request only verifier stats */
+		log_level = 4 | (env.log_fixed ? 8 : 0);
 	}
 	verif_log_buf[0] = '\0';
 
+	bpf_program__set_log_buf(prog, buf, buf_sz);
+	bpf_program__set_log_level(prog, log_level);
+
 	/* increase chances of successful BPF object loading */
 	fixup_obj(obj);
 
-- 
2.34.1

[PATCH bpf-next 6/6] selftests/bpf: add fixed vs rotating verifier log tests

[Andrii Nakryiko]

Add selftests validating BPF_LOG_FIXED behavior, which used to be the
only behavior, and now default rotating BPF verifier log, which returns
just up to last N bytes of full verifier log, instead of returning
-ENOSPC.

To stress test correctness of in-kernel verifier log logic, we force it
to truncate program's verifier log to all lengths from 1 all the way to
its full size (about 450 bytes today). This was a useful stress test
while developing the feature.

Signed-off-by: Andrii Nakryiko <andrii@kernel.org>
---
 .../selftests/bpf/prog_tests/verifier_log.c   | 89 +++++++++++++++++++
 1 file changed, 89 insertions(+)
 create mode 100644 tools/testing/selftests/bpf/prog_tests/verifier_log.c

diff --git a/tools/testing/selftests/bpf/prog_tests/verifier_log.c b/tools/testing/selftests/bpf/prog_tests/verifier_log.c
new file mode 100644
index 000000000000..4d9630d74ae0
--- /dev/null
+++ b/tools/testing/selftests/bpf/prog_tests/verifier_log.c
@@ -0,0 +1,89 @@
+// SPDX-License-Identifier: GPL-2.0
+/* Copyright (c) 2023 Meta Platforms, Inc. and affiliates. */
+
+#include <test_progs.h>
+#include <bpf/btf.h>
+
+#include "test_log_buf.skel.h"
+
+void test_verifier_log(void)
+{
+	LIBBPF_OPTS(bpf_prog_load_opts, opts);
+	char full_log[1024], log_buf[1024], *exp_log;
+	char prog_name[16], op_name[32];
+	struct test_log_buf *skel;
+	const struct bpf_insn *insns;
+	size_t insn_cnt, fixed_log_sz;
+	int i, err, prog_fd;
+
+	skel = test_log_buf__open();
+	if (!ASSERT_OK_PTR(skel, "skel_open"))
+		return;
+
+	bpf_program__set_autoload(skel->progs.bad_prog, false);
+
+	err = test_log_buf__load(skel);
+	if (!ASSERT_OK(err, "skel_load"))
+		goto cleanup;
+
+	insns = bpf_program__insns(skel->progs.good_prog);
+	insn_cnt = bpf_program__insn_cnt(skel->progs.good_prog);
+
+	opts.log_buf = full_log;
+	opts.log_size = sizeof(full_log);
+	opts.log_level = 2 | 8 /* BPF_LOG_FIXED */;
+	prog_fd = bpf_prog_load(BPF_PROG_TYPE_RAW_TRACEPOINT, "log_fixed",
+				"GPL", insns, insn_cnt, &opts);
+	if (!ASSERT_GT(prog_fd, 0, "fixed_log_prog_load"))
+		goto cleanup;
+	close(prog_fd);
+
+	fixed_log_sz = strlen(full_log) + 1;
+	if (!ASSERT_GT(fixed_log_sz, 100, "fixed_log_sz"))
+		goto cleanup;
+
+	/* validate BPF_LOG_FIXED works as verifier log used to work, that is:
+	 * we get -ENOSPC and beginning of the full verifier log
+	 */
+	opts.log_buf = log_buf;
+	opts.log_level = 2 | 8; /* verbose level 2, fixed-length log */
+	opts.log_size = 50;
+
+	prog_fd = bpf_prog_load(BPF_PROG_TYPE_RAW_TRACEPOINT, "log_fixed50",
+				"GPL", insns, insn_cnt, &opts);
+	if (!ASSERT_EQ(prog_fd, -ENOSPC, "unexpected_log_fixed_prog_load_result")) {
+		if (prog_fd >= 0)
+			close(prog_fd);
+		goto cleanup;
+	}
+	if (!ASSERT_EQ(strlen(log_buf), 49, "log_fixed_50"))
+		goto cleanup;
+	if (!ASSERT_STRNEQ(log_buf, full_log, 49, op_name))
+		goto cleanup;
+
+	/* validate rolling verifier log logic: try all variations of log buf
+	 * length to force various truncation scenarios
+	 */
+	opts.log_buf = log_buf;
+	opts.log_level = 2; /* verbose level 2, rolling log */
+	for (i = 1; i <= fixed_log_sz; i++) {
+		opts.log_size = i;
+
+		snprintf(prog_name, sizeof(prog_name), "log_roll_%d", i);
+		prog_fd = bpf_prog_load(BPF_PROG_TYPE_RAW_TRACEPOINT, prog_name,
+					"GPL", insns, insn_cnt, &opts);
+
+		snprintf(op_name, sizeof(op_name), "log_roll_prog_load_%d", i);
+		if (!ASSERT_GT(prog_fd, 0, op_name))
+			goto cleanup;
+		close(prog_fd);
+
+		exp_log = full_log + fixed_log_sz - i;
+		snprintf(op_name, sizeof(op_name), "log_roll_contents_%d", i);
+		if (!ASSERT_STREQ(log_buf, exp_log, op_name))
+			goto cleanup;
+	}
+
+cleanup:
+	test_log_buf__destroy(skel);
+}
-- 
2.34.1

Re: [PATCH bpf-next 3/6] bpf: switch BPF verifier log to be a rotating log by default

[Alexei Starovoitov]

On Thu, Mar 16, 2023 at 11:30:10AM -0700, Andrii Nakryiko wrote:
> Currently, if user-supplied log buffer to collect BPF verifier log turns
> out to be too small to contain full log, bpf() syscall return -ENOSPC,
> fails BPF program verification/load, but preserves first N-1 bytes of
> verifier log (where N is the size of user-supplied buffer).
> 
> This is problematic in a bunch of common scenarios, especially when
> working with real-world BPF programs that tend to be pretty complex as
> far as verification goes and require big log buffers. Typically, it's
> when debugging tricky cases at log level 2 (verbose). Also, when BPF program
> is successfully validated, log level 2 is the only way to actually see
> verifier state progression and all the important details.
> 
> Even with log level 1, it's possible to get -ENOSPC even if the final
> verifier log fits in log buffer, if there is a code path that's deep
> enough to fill up entire log, even if normally it would be reset later
> on (there is a logic to chop off successfully validated portions of BPF
> verifier log).
> 
> In short, it's not always possible to pre-size log buffer. Also, in
> practice, the end of the log most often is way more important than the
> beginning.
> 
> This patch switches BPF verifier log behavior to effectively behave as
> rotating log. That is, if user-supplied log buffer turns out to be too
> short, instead of failing with -ENOSPC, verifier will keep overwriting
> previously written log, effectively treating user's log buffer as a ring
> buffer.
> 
> Importantly, though, to preserve good user experience and not require
> every user-space application to adopt to this new behavior, before
> exiting to user-space verifier will rotate log (in place) to make it
> start at the very beginning of user buffer as a continuous
> zero-terminated string. The contents will be a chopped off N-1 last
> bytes of full verifier log, of course.
> 
> Given beginning of log is sometimes important as well, we add
> BPF_LOG_FIXED (which equals 8) flag to force old behavior, which allows
> tools like veristat to request first part of verifier log, if necessary.
> 
> On the implementation side, conceptually, it's all simple. We maintain
> 64-bit logical start and end positions. If we need to truncate the log,
> start position will be adjusted accordingly to lag end position by
> N bytes. We then use those logical positions to calculate their matching
> actual positions in user buffer and handle wrap around the end of the
> buffer properly. Finally, right before returning from bpf_check(), we
> rotate user log buffer contents in-place as necessary, to make log
> contents contiguous. See comments in relevant functions for details.
> 
> Signed-off-by: Andrii Nakryiko <andrii@kernel.org>
> ---
>  include/linux/bpf_verifier.h                  |  32 ++-
>  kernel/bpf/log.c                              | 182 +++++++++++++++++-
>  kernel/bpf/verifier.c                         |  17 +-
>  .../selftests/bpf/prog_tests/log_fixup.c      |   1 +
>  4 files changed, 209 insertions(+), 23 deletions(-)
> 
> diff --git a/include/linux/bpf_verifier.h b/include/linux/bpf_verifier.h
> index 83dff25545ee..cff11c99ed9a 100644
> --- a/include/linux/bpf_verifier.h
> +++ b/include/linux/bpf_verifier.h
> @@ -491,25 +491,42 @@ struct bpf_insn_aux_data {
>  #define BPF_VERIFIER_TMP_LOG_SIZE	1024
>  
>  struct bpf_verifier_log {
> -	u32 level;
> -	char kbuf[BPF_VERIFIER_TMP_LOG_SIZE];
> +	/* Logical start and end positions of a "log window" of the verifier log.
> +	 * start_pos == 0 means we haven't truncated anything.
> +	 * Once truncation starts to happen, start_pos + len_total == end_pos,
> +	 * except during log reset situations, in which (end_pos - start_pos)
> +	 * might get smaller than len_total (see bpf_vlog_reset()).
> +	 * Generally, (end_pos - start_pos) gives number of useful data in
> +	 * user log buffer.
> +	 */
> +	u64 start_pos;
> +	u64 end_pos;
...
>  
> -void bpf_vlog_reset(struct bpf_verifier_log *log, u32 new_pos)
> +void bpf_vlog_reset(struct bpf_verifier_log *log, u64 new_pos)
>  {
>  	char zero = 0;
>  
>  	if (!bpf_verifier_log_needed(log))
>  		return;
>  
> -	log->len_used = new_pos;
> +	/* if position to which we reset is beyond current log window, then we
> +	 * didn't preserve any useful content and should adjust adjust
> +	 * start_pos to end up with an empty log (start_pos == end_pos)
> +	 */
> +	log->end_pos = new_pos;
> +	if (log->end_pos < log->start_pos)
> +		log->start_pos = log->end_pos;
> +
>  	if (put_user(zero, log->ubuf + new_pos))

Haven't analyzed the code in details and asking based on comments...
new_pos can be bigger than ubuf size and above write will be out of bounds, no?

Re: [PATCH bpf-next 3/6] bpf: switch BPF verifier log to be a rotating log by default

[kernel test robot]

Hi Andrii,

I love your patch! Yet something to improve:

[auto build test ERROR on bpf-next/master]

url:    https://github.com/intel-lab-lkp/linux/commits/Andrii-Nakryiko/bpf-split-off-basic-BPF-verifier-log-into-separate-file/20230317-023431
base:   https://git.kernel.org/pub/scm/linux/kernel/git/bpf/bpf-next.git master
patch link:    https://lore.kernel.org/r/20230316183013.2882810-4-andrii%40kernel.org
patch subject: [PATCH bpf-next 3/6] bpf: switch BPF verifier log to be a rotating log by default
config: i386-randconfig-a002-20230313 (https://download.01.org/0day-ci/archive/20230317/202303171242.biyrTbVN-lkp@intel.com/config)
compiler: gcc-11 (Debian 11.3.0-8) 11.3.0
reproduce (this is a W=1 build):
        # https://github.com/intel-lab-lkp/linux/commit/f2876fe2427e5bdfbbb27980025b969c93f46c4b
        git remote add linux-review https://github.com/intel-lab-lkp/linux
        git fetch --no-tags linux-review Andrii-Nakryiko/bpf-split-off-basic-BPF-verifier-log-into-separate-file/20230317-023431
        git checkout f2876fe2427e5bdfbbb27980025b969c93f46c4b
        # save the config file
        mkdir build_dir && cp config build_dir/.config
        make W=1 O=build_dir ARCH=i386 olddefconfig
        make W=1 O=build_dir ARCH=i386 SHELL=/bin/bash

If you fix the issue, kindly add following tag where applicable
| Reported-by: kernel test robot <lkp@intel.com>
| Link: https://lore.kernel.org/oe-kbuild-all/202303171242.biyrTbVN-lkp@intel.com/

All errors (new ones prefixed by >>):

   ld: kernel/bpf/log.o: in function `bpf_verifier_vlog':
>> kernel/bpf/log.c:59: undefined reference to `__umoddi3'
>> ld: kernel/bpf/log.c:60: undefined reference to `__umoddi3'
   ld: kernel/bpf/log.o: in function `bpf_vlog_finalize':
   kernel/bpf/log.c:212: undefined reference to `__umoddi3'


vim +59 kernel/bpf/log.c

    17	
    18	void bpf_verifier_vlog(struct bpf_verifier_log *log, const char *fmt,
    19			       va_list args)
    20	{
    21		unsigned int n;
    22	
    23		n = vscnprintf(log->kbuf, BPF_VERIFIER_TMP_LOG_SIZE, fmt, args);
    24	
    25		WARN_ONCE(n >= BPF_VERIFIER_TMP_LOG_SIZE - 1,
    26			  "verifier log line truncated - local buffer too short\n");
    27	
    28		if (log->level == BPF_LOG_KERNEL) {
    29			bool newline = n > 0 && log->kbuf[n - 1] == '\n';
    30	
    31			pr_err("BPF: %s%s", log->kbuf, newline ? "" : "\n");
    32			return;
    33		}
    34	
    35		if (log->level & BPF_LOG_FIXED) {
    36			n = min(log->len_total - bpf_log_used(log) - 1, n);
    37			log->kbuf[n] = '\0';
    38			n += 1;
    39	
    40			if (copy_to_user(log->ubuf + log->end_pos, log->kbuf, n))
    41				goto fail;
    42	
    43			log->end_pos += n - 1; /* don't count terminating '\0' */
    44		} else {
    45			u64 new_end, new_start, cur_pos;
    46			u32 buf_start, buf_end, new_n;
    47	
    48			log->kbuf[n] = '\0';
    49			n += 1;
    50	
    51			new_end = log->end_pos + n;
    52			if (new_end - log->start_pos >= log->len_total)
    53				new_start = new_end - log->len_total;
    54			else
    55				new_start = log->start_pos;
    56			new_n = min(n, log->len_total);
    57			cur_pos = new_end - new_n;
    58	
  > 59			buf_start = cur_pos % log->len_total;
  > 60			buf_end = new_end % log->len_total;
    61			/* new_end and buf_end are exclusive indices, so if buf_end is
    62			 * exactly zero, then it actually points right to the end of
    63			 * ubuf and there is no wrap around
    64			 */
    65			if (buf_end == 0)
    66				buf_end = log->len_total;
    67	
    68			/* if buf_start > buf_end, we wrapped around;
    69			 * if buf_start == buf_end, then we fill ubuf completely; we
    70			 * can't have buf_start == buf_end to mean that there is
    71			 * nothing to write, because we always write at least
    72			 * something, even if terminal '\0'
    73			 */
    74			if (buf_start < buf_end) {
    75				/* message fits within contiguous chunk of ubuf */
    76				if (copy_to_user(log->ubuf + buf_start,
    77						 log->kbuf + n - new_n,
    78						 buf_end - buf_start))
    79					goto fail;
    80			} else {
    81				/* message wraps around the end of ubuf, copy in two chunks */
    82				if (copy_to_user(log->ubuf + buf_start,
    83						 log->kbuf + n - new_n,
    84						 log->len_total - buf_start))
    85					goto fail;
    86				if (copy_to_user(log->ubuf,
    87						 log->kbuf + n - buf_end,
    88						 buf_end))
    89					goto fail;
    90			}
    91	
    92			log->start_pos = new_start;
    93			log->end_pos = new_end - 1; /* don't count terminating '\0' */
    94		}
    95	
    96		return;
    97	fail:
    98		log->ubuf = NULL;
    99	}
   100	

-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests

Re: [PATCH bpf-next 3/6] bpf: switch BPF verifier log to be a rotating log by default

[kernel test robot]

Hi Andrii,

I love your patch! Yet something to improve:

[auto build test ERROR on bpf-next/master]

url:    https://github.com/intel-lab-lkp/linux/commits/Andrii-Nakryiko/bpf-split-off-basic-BPF-verifier-log-into-separate-file/20230317-023431
base:   https://git.kernel.org/pub/scm/linux/kernel/git/bpf/bpf-next.git master
patch link:    https://lore.kernel.org/r/20230316183013.2882810-4-andrii%40kernel.org
patch subject: [PATCH bpf-next 3/6] bpf: switch BPF verifier log to be a rotating log by default
config: arm-randconfig-r046-20230312 (https://download.01.org/0day-ci/archive/20230317/202303171418.1wRw0c8S-lkp@intel.com/config)
compiler: clang version 17.0.0 (https://github.com/llvm/llvm-project 67409911353323ca5edf2049ef0df54132fa1ca7)
reproduce (this is a W=1 build):
        wget https://raw.githubusercontent.com/intel/lkp-tests/master/sbin/make.cross -O ~/bin/make.cross
        chmod +x ~/bin/make.cross
        # install arm cross compiling tool for clang build
        # apt-get install binutils-arm-linux-gnueabi
        # https://github.com/intel-lab-lkp/linux/commit/f2876fe2427e5bdfbbb27980025b969c93f46c4b
        git remote add linux-review https://github.com/intel-lab-lkp/linux
        git fetch --no-tags linux-review Andrii-Nakryiko/bpf-split-off-basic-BPF-verifier-log-into-separate-file/20230317-023431
        git checkout f2876fe2427e5bdfbbb27980025b969c93f46c4b
        # save the config file
        mkdir build_dir && cp config build_dir/.config
        COMPILER_INSTALL_PATH=$HOME/0day COMPILER=clang make.cross W=1 O=build_dir ARCH=arm olddefconfig
        COMPILER_INSTALL_PATH=$HOME/0day COMPILER=clang make.cross W=1 O=build_dir ARCH=arm SHELL=/bin/bash

If you fix the issue, kindly add following tag where applicable
| Reported-by: kernel test robot <lkp@intel.com>
| Link: https://lore.kernel.org/oe-kbuild-all/202303171418.1wRw0c8S-lkp@intel.com/

All errors (new ones prefixed by >>):

>> ld.lld: error: undefined symbol: __aeabi_uldivmod
   >>> referenced by log.c
   >>>               kernel/bpf/log.o:(bpf_verifier_vlog) in archive vmlinux.a
   >>> referenced by log.c
   >>>               kernel/bpf/log.o:(bpf_verifier_vlog) in archive vmlinux.a
   >>> referenced by log.c
   >>>               kernel/bpf/log.o:(bpf_vlog_finalize) in archive vmlinux.a
   >>> did you mean: __aeabi_uidivmod
   >>> defined in: vmlinux.a(arch/arm/lib/lib1funcs.o)

-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests

Re: [PATCH bpf-next 3/6] bpf: switch BPF verifier log to be a rotating log by default

[kernel test robot]

Hi Andrii,

I love your patch! Yet something to improve:

[auto build test ERROR on bpf-next/master]

url:    https://github.com/intel-lab-lkp/linux/commits/Andrii-Nakryiko/bpf-split-off-basic-BPF-verifier-log-into-separate-file/20230317-023431
base:   https://git.kernel.org/pub/scm/linux/kernel/git/bpf/bpf-next.git master
patch link:    https://lore.kernel.org/r/20230316183013.2882810-4-andrii%40kernel.org
patch subject: [PATCH bpf-next 3/6] bpf: switch BPF verifier log to be a rotating log by default
config: m68k-buildonly-randconfig-r001-20230312 (https://download.01.org/0day-ci/archive/20230317/202303171434.ljQyQS6z-lkp@intel.com/config)
compiler: m68k-linux-gcc (GCC) 12.1.0
reproduce (this is a W=1 build):
        wget https://raw.githubusercontent.com/intel/lkp-tests/master/sbin/make.cross -O ~/bin/make.cross
        chmod +x ~/bin/make.cross
        # https://github.com/intel-lab-lkp/linux/commit/f2876fe2427e5bdfbbb27980025b969c93f46c4b
        git remote add linux-review https://github.com/intel-lab-lkp/linux
        git fetch --no-tags linux-review Andrii-Nakryiko/bpf-split-off-basic-BPF-verifier-log-into-separate-file/20230317-023431
        git checkout f2876fe2427e5bdfbbb27980025b969c93f46c4b
        # save the config file
        mkdir build_dir && cp config build_dir/.config
        COMPILER_INSTALL_PATH=$HOME/0day COMPILER=gcc-12.1.0 make.cross W=1 O=build_dir ARCH=m68k olddefconfig
        COMPILER_INSTALL_PATH=$HOME/0day COMPILER=gcc-12.1.0 make.cross W=1 O=build_dir ARCH=m68k SHELL=/bin/bash

If you fix the issue, kindly add following tag where applicable
| Reported-by: kernel test robot <lkp@intel.com>
| Link: https://lore.kernel.org/oe-kbuild-all/202303171434.ljQyQS6z-lkp@intel.com/

All errors (new ones prefixed by >>):

   m68k-linux-ld: section .rodata VMA [0000000000001000,00000000004e5d2f] overlaps section .text VMA [0000000000000400,0000000000628bcf]
   m68k-linux-ld: m68k-linux-ld: DWARF error: could not find abbrev number 119
   kernel/bpf/log.o: in function `bpf_verifier_vlog':
>> log.c:(.text+0x2fe): undefined reference to `__umoddi3'
>> m68k-linux-ld: log.c:(.text+0x332): undefined reference to `__umoddi3'
   m68k-linux-ld: kernel/bpf/log.o: in function `bpf_vlog_finalize':
   log.c:(.text+0x570): undefined reference to `__umoddi3'

-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests

Re: [PATCH bpf-next 3/6] bpf: switch BPF verifier log to be a rotating log by default

[Eduard Zingerman]

On Thu, 2023-03-16 at 11:30 -0700, Andrii Nakryiko wrote:
> Currently, if user-supplied log buffer to collect BPF verifier log turns
> out to be too small to contain full log, bpf() syscall return -ENOSPC,
> fails BPF program verification/load, but preserves first N-1 bytes of
> verifier log (where N is the size of user-supplied buffer).
> 
> This is problematic in a bunch of common scenarios, especially when
> working with real-world BPF programs that tend to be pretty complex as
> far as verification goes and require big log buffers. Typically, it's
> when debugging tricky cases at log level 2 (verbose). Also, when BPF program
> is successfully validated, log level 2 is the only way to actually see
> verifier state progression and all the important details.
> 
> Even with log level 1, it's possible to get -ENOSPC even if the final
> verifier log fits in log buffer, if there is a code path that's deep
> enough to fill up entire log, even if normally it would be reset later
> on (there is a logic to chop off successfully validated portions of BPF
> verifier log).
> 
> In short, it's not always possible to pre-size log buffer. Also, in
> practice, the end of the log most often is way more important than the
> beginning.
> 
> This patch switches BPF verifier log behavior to effectively behave as
> rotating log. That is, if user-supplied log buffer turns out to be too
> short, instead of failing with -ENOSPC, verifier will keep overwriting
> previously written log, effectively treating user's log buffer as a ring
> buffer.
> 
> Importantly, though, to preserve good user experience and not require
> every user-space application to adopt to this new behavior, before
> exiting to user-space verifier will rotate log (in place) to make it
> start at the very beginning of user buffer as a continuous
> zero-terminated string. The contents will be a chopped off N-1 last
> bytes of full verifier log, of course.
> 
> Given beginning of log is sometimes important as well, we add
> BPF_LOG_FIXED (which equals 8) flag to force old behavior, which allows
> tools like veristat to request first part of verifier log, if necessary.
> 
> On the implementation side, conceptually, it's all simple. We maintain
> 64-bit logical start and end positions. If we need to truncate the log,
> start position will be adjusted accordingly to lag end position by
> N bytes. We then use those logical positions to calculate their matching
> actual positions in user buffer and handle wrap around the end of the
> buffer properly. Finally, right before returning from bpf_check(), we
> rotate user log buffer contents in-place as necessary, to make log
> contents contiguous. See comments in relevant functions for details.
> 
> Signed-off-by: Andrii Nakryiko <andrii@kernel.org>

I tried bpf_verifier_vlog() and bpf_vlog_finalize() using some
randomized testing + valgrind and everything seems to be fine.
Tbh, it seems to me that having kunit tests for things like this might
be a good idea.

Test script for reference:

  void once(char *in, size_t out_sz) {
  	struct bpf_verifier_log log = {};
  	char *out = calloc(out_sz, 1);
  	size_t in_sz = strlen(in);
  	size_t orig_out_sz = out_sz;
  
  	log.ubuf = out;
  	log.len_total = out_sz;
  	log.level = 1 | 2 | 4;
  
  	for (char *input = strtok(in, " "); input; input = strtok(NULL, " "))
  		bpf_verifier_vlog(&log, input);
  
  	bpf_vlog_finalize(&log);
  
  	for (unsigned i = 0; i < in_sz; ++i)
  		if (in[i] == 0)
  			in[i] = ' ';
  
  	out_sz = strlen(out);
  	if (in_sz)
  		--in_sz;
  	if (out_sz)
  		--out_sz;
  	while (out_sz > 0 && in_sz > 0) {
  		if (in[in_sz] == ' ') {
  			--in_sz;
  			continue;
  		}
  		if (in[in_sz] == out[out_sz]) {
  			--in_sz;
  			--out_sz;
  			continue;
  		}
  		printf("    in: '%s'\n", in);
  		printf("   out: '%s'\n", out);
  		printf("err at: %lu\n", out_sz);
  		printf("out_sz: %lu\n", orig_out_sz);
  		break;
  	}
  
  	free(out);
  }
  
  void rnd_once() {
  	char in[1024] = {};
  	size_t out_sz = 1 + rand() % 100;
  	size_t in_sz = rand() % (sizeof(in) - 1);
  	int cnt = 0;
  
  	for (unsigned i = 0; i < in_sz; ++i)
  		if (rand() % 100 < 7)
  			in[i] = ' ';
  		else
  			in[i] = 'a' + (rand() % 26);
  
  	once(in, out_sz);
  }
  
  int main(int argc, char **argv) {
	if (argc == 3) {
		once(argv[2], atoi(argv[1]));
	} else {
		srand(clock());
		for (int i = 0; i < 100000; ++i)
			rnd_once();
	}
  }

Tested-by: Eduard Zingerman <eddyz87@gmail.com>

> ---
>  include/linux/bpf_verifier.h                  |  32 ++-
>  kernel/bpf/log.c                              | 182 +++++++++++++++++-
>  kernel/bpf/verifier.c                         |  17 +-
>  .../selftests/bpf/prog_tests/log_fixup.c      |   1 +
>  4 files changed, 209 insertions(+), 23 deletions(-)
> 
> diff --git a/include/linux/bpf_verifier.h b/include/linux/bpf_verifier.h
> index 83dff25545ee..cff11c99ed9a 100644
> --- a/include/linux/bpf_verifier.h
> +++ b/include/linux/bpf_verifier.h
> @@ -491,25 +491,42 @@ struct bpf_insn_aux_data {
>  #define BPF_VERIFIER_TMP_LOG_SIZE	1024
>  
>  struct bpf_verifier_log {
> -	u32 level;
> -	char kbuf[BPF_VERIFIER_TMP_LOG_SIZE];
> +	/* Logical start and end positions of a "log window" of the verifier log.
> +	 * start_pos == 0 means we haven't truncated anything.
> +	 * Once truncation starts to happen, start_pos + len_total == end_pos,
> +	 * except during log reset situations, in which (end_pos - start_pos)
> +	 * might get smaller than len_total (see bpf_vlog_reset()).
> +	 * Generally, (end_pos - start_pos) gives number of useful data in
> +	 * user log buffer.
> +	 */
> +	u64 start_pos;
> +	u64 end_pos;
>  	char __user *ubuf;
> -	u32 len_used;
> +	u32 level;
>  	u32 len_total;
> +	char kbuf[BPF_VERIFIER_TMP_LOG_SIZE];
>  };
>  
>  #define BPF_LOG_LEVEL1	1
>  #define BPF_LOG_LEVEL2	2
>  #define BPF_LOG_STATS	4
> +#define BPF_LOG_FIXED	8
>  #define BPF_LOG_LEVEL	(BPF_LOG_LEVEL1 | BPF_LOG_LEVEL2)
> -#define BPF_LOG_MASK	(BPF_LOG_LEVEL | BPF_LOG_STATS)
> +#define BPF_LOG_MASK	(BPF_LOG_LEVEL | BPF_LOG_STATS | BPF_LOG_FIXED)
>  #define BPF_LOG_KERNEL	(BPF_LOG_MASK + 1) /* kernel internal flag */
>  #define BPF_LOG_MIN_ALIGNMENT 8U
>  #define BPF_LOG_ALIGNMENT 40U
>  
> +static inline u32 bpf_log_used(const struct bpf_verifier_log *log)
> +{
> +	return log->end_pos - log->start_pos;
> +}
> +
>  static inline bool bpf_verifier_log_full(const struct bpf_verifier_log *log)
>  {
> -	return log->len_used >= log->len_total - 1;
> +	if (log->level & BPF_LOG_FIXED)
> +		return bpf_log_used(log) >= log->len_total - 1;
> +	return false;
>  }
>  
>  static inline bool bpf_verifier_log_needed(const struct bpf_verifier_log *log)
> @@ -596,7 +613,7 @@ struct bpf_verifier_env {
>  	u32 scratched_regs;
>  	/* Same as scratched_regs but for stack slots */
>  	u64 scratched_stack_slots;
> -	u32 prev_log_len, prev_insn_print_len;
> +	u64 prev_log_pos, prev_insn_print_pos;
>  	/* buffer used in reg_type_str() to generate reg_type string */
>  	char type_str_buf[TYPE_STR_BUF_LEN];
>  };
> @@ -608,7 +625,8 @@ __printf(2, 3) void bpf_verifier_log_write(struct bpf_verifier_env *env,
>  					   const char *fmt, ...);
>  __printf(2, 3) void bpf_log(struct bpf_verifier_log *log,
>  			    const char *fmt, ...);
> -void bpf_vlog_reset(struct bpf_verifier_log *log, u32 new_pos);
> +void bpf_vlog_reset(struct bpf_verifier_log *log, u64 new_pos);
> +void bpf_vlog_finalize(struct bpf_verifier_log *log);
>  
>  static inline struct bpf_func_state *cur_func(struct bpf_verifier_env *env)
>  {
> diff --git a/kernel/bpf/log.c b/kernel/bpf/log.c
> index 1974891fc324..ec640828e84e 100644
> --- a/kernel/bpf/log.c
> +++ b/kernel/bpf/log.c
> @@ -32,26 +32,192 @@ void bpf_verifier_vlog(struct bpf_verifier_log *log, const char *fmt,
>  		return;
>  	}
>  
> -	n = min(log->len_total - log->len_used - 1, n);
> -	log->kbuf[n] = '\0';
> -	if (!copy_to_user(log->ubuf + log->len_used, log->kbuf, n + 1))
> -		log->len_used += n;
> -	else
> -		log->ubuf = NULL;
> +	if (log->level & BPF_LOG_FIXED) {
> +		n = min(log->len_total - bpf_log_used(log) - 1, n);
> +		log->kbuf[n] = '\0';
> +		n += 1;
> +
> +		if (copy_to_user(log->ubuf + log->end_pos, log->kbuf, n))
> +			goto fail;
> +
> +		log->end_pos += n - 1; /* don't count terminating '\0' */
> +	} else {
> +		u64 new_end, new_start, cur_pos;
> +		u32 buf_start, buf_end, new_n;
> +
> +		log->kbuf[n] = '\0';
> +		n += 1;
> +
> +		new_end = log->end_pos + n;
> +		if (new_end - log->start_pos >= log->len_total)
> +			new_start = new_end - log->len_total;
> +		else
> +			new_start = log->start_pos;
> +		new_n = min(n, log->len_total);
> +		cur_pos = new_end - new_n;
> +
> +		buf_start = cur_pos % log->len_total;
> +		buf_end = new_end % log->len_total;
> +		/* new_end and buf_end are exclusive indices, so if buf_end is
> +		 * exactly zero, then it actually points right to the end of
> +		 * ubuf and there is no wrap around
> +		 */
> +		if (buf_end == 0)
> +			buf_end = log->len_total;
> +
> +		/* if buf_start > buf_end, we wrapped around;
> +		 * if buf_start == buf_end, then we fill ubuf completely; we
> +		 * can't have buf_start == buf_end to mean that there is
> +		 * nothing to write, because we always write at least
> +		 * something, even if terminal '\0'
> +		 */
> +		if (buf_start < buf_end) {
> +			/* message fits within contiguous chunk of ubuf */
> +			if (copy_to_user(log->ubuf + buf_start,
> +					 log->kbuf + n - new_n,
> +					 buf_end - buf_start))
> +				goto fail;
> +		} else {
> +			/* message wraps around the end of ubuf, copy in two chunks */
> +			if (copy_to_user(log->ubuf + buf_start,
> +					 log->kbuf + n - new_n,
> +					 log->len_total - buf_start))
> +				goto fail;
> +			if (copy_to_user(log->ubuf,
> +					 log->kbuf + n - buf_end,
> +					 buf_end))
> +				goto fail;
> +		}
> +
> +		log->start_pos = new_start;
> +		log->end_pos = new_end - 1; /* don't count terminating '\0' */
> +	}
> +
> +	return;
> +fail:
> +	log->ubuf = NULL;
>  }
>  
> -void bpf_vlog_reset(struct bpf_verifier_log *log, u32 new_pos)
> +void bpf_vlog_reset(struct bpf_verifier_log *log, u64 new_pos)
>  {
>  	char zero = 0;
>  
>  	if (!bpf_verifier_log_needed(log))
>  		return;
>  
> -	log->len_used = new_pos;
> +	/* if position to which we reset is beyond current log window, then we
> +	 * didn't preserve any useful content and should adjust adjust
> +	 * start_pos to end up with an empty log (start_pos == end_pos)
> +	 */
> +	log->end_pos = new_pos;
> +	if (log->end_pos < log->start_pos)
> +		log->start_pos = log->end_pos;
> +
>  	if (put_user(zero, log->ubuf + new_pos))
>  		log->ubuf = NULL;
>  }
>  
> +static void bpf_vlog_reverse_kbuf(char *buf, int len)
> +{
> +	int i, j;
> +
> +	for (i = 0, j = len - 1; i < j; i++, j--)
> +		swap(buf[i], buf[j]);
> +}
> +
> +static int bpf_vlog_reverse_ubuf(struct bpf_verifier_log *log, int start, int end)
> +{
> +	/* we split log->kbuf into two equal parts for both ends of array */
> +	int n = sizeof(log->kbuf) / 2, nn;
> +	char *lbuf = log->kbuf, *rbuf = log->kbuf + n;
> +
> +	/* Read ubuf's section [start, end) two chunks at a time, from left
> +	 * and right side; within each chunk, swap all the bytes; after that
> +	 * reverse the order of lbuf and rbuf and write result back to ubuf.
> +	 * This way we'll end up with swapped contents of specified
> +	 * [start, end) ubuf segment.
> +	 */
> +	while (end - start > 1) {
> +		nn = min(n, (end - start ) / 2);
> +
> +		if (copy_from_user(lbuf, log->ubuf + start, nn))
> +			return -EFAULT;
> +		if (copy_from_user(rbuf, log->ubuf + end - nn, nn))
> +			return -EFAULT;
> +
> +		bpf_vlog_reverse_kbuf(lbuf, nn);
> +		bpf_vlog_reverse_kbuf(rbuf, nn);
> +
> +		/* we write lbuf to the right end of ubuf, while rbuf to the
> +		 * left one to end up with properly reversed overall ubuf
> +		 */
> +		if (copy_to_user(log->ubuf + start, rbuf, nn))
> +			return -EFAULT;
> +		if (copy_to_user(log->ubuf + end - nn, lbuf, nn))
> +			return -EFAULT;
> +
> +		start += nn;
> +		end -= nn;
> +	}
> +
> +	return 0;
> +}
> +
> +void bpf_vlog_finalize(struct bpf_verifier_log *log)
> +{
> +	u32 sublen;
> +	int err;
> +
> +	if (!log || !log->level || !log->ubuf)
> +		return;
> +	if ((log->level & BPF_LOG_FIXED) || log->level == BPF_LOG_KERNEL)
> +		return;
> +
> +	/* If we never truncated log, there is nothing to move around. */
> +	if (log->start_pos == 0)
> +		return;
> +
> +	/* Otherwise we need to rotate log contents to make it start from the
> +	 * buffer beginning and be a continuous zero-terminated string. Note
> +	 * that if log->start_pos != 0 then we definitely filled up entire log
> +	 * buffer with no gaps, and we just need to shift buffer contents to
> +	 * the left by (log->start_pos % log->len_total) bytes.
> +	 *
> +	 * Unfortunately, user buffer could be huge and we don't want to
> +	 * allocate temporary kernel memory of the same size just to shift
> +	 * contents in a straightforward fashion. Instead, we'll be clever and
> +	 * do in-place array rotation. This is a leetcode-style problem, which
> +	 * could be solved by three rotations.
> +	 *
> +	 * Let's say we have log buffer that has to be shifted left by 7 bytes
> +	 * (spaces and vertical bar is just for demonstrative purposes):
> +	 *   E F G H I J K | A B C D
> +	 *
> +	 * First, we reverse entire array:
> +	 *   D C B A | K J I H G F E
> +	 *
> +	 * Then we rotate first 4 bytes (DCBA) and separately last 7 bytes
> +	 * (KJIHGFE), resulting in a properly rotated array:
> +	 *   A B C D | E F G H I J K
> +	 *
> +	 * We'll utilize log->kbuf to read user memory chunk by chunk, swap
> +	 * bytes, and write them back. Doing it byte-by-byte would be
> +	 * unnecessarily inefficient. Altogether we are going to read and
> +	 * write each byte twice.
> +	 */
> +
> +	/* length of the chopped off part that will be the beginning;
> +	 * len(ABCD) in the example above
> +	 */
> +	sublen = log->len_total - (log->start_pos % log->len_total);
> +
> +	err = bpf_vlog_reverse_ubuf(log, 0, log->len_total);
> +	err = err ?: bpf_vlog_reverse_ubuf(log, 0, sublen);
> +	err = err ?: bpf_vlog_reverse_ubuf(log, sublen, log->len_total);
> +	if (err)
> +		log->ubuf = NULL;
> +}
> +
>  /* log_level controls verbosity level of eBPF verifier.
>   * bpf_verifier_log_write() is used to dump the verification trace to the log,
>   * so the user can figure out what's wrong with the program
> diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
> index 203d6e644e44..f6d3d448e1b1 100644
> --- a/kernel/bpf/verifier.c
> +++ b/kernel/bpf/verifier.c
> @@ -1435,10 +1435,10 @@ static inline u32 vlog_alignment(u32 pos)
>  static void print_insn_state(struct bpf_verifier_env *env,
>  			     const struct bpf_func_state *state)
>  {
> -	if (env->prev_log_len && env->prev_log_len == env->log.len_used) {
> +	if (env->prev_log_pos && env->prev_log_pos == env->log.end_pos) {
>  		/* remove new line character */
> -		bpf_vlog_reset(&env->log, env->prev_log_len - 1);
> -		verbose(env, "%*c;", vlog_alignment(env->prev_insn_print_len), ' ');
> +		bpf_vlog_reset(&env->log, env->prev_log_pos - 1);
> +		verbose(env, "%*c;", vlog_alignment(env->prev_insn_print_pos), ' ');
>  	} else {
>  		verbose(env, "%d:", env->insn_idx);
>  	}
> @@ -1746,7 +1746,7 @@ static struct bpf_verifier_state *push_stack(struct bpf_verifier_env *env,
>  	elem->insn_idx = insn_idx;
>  	elem->prev_insn_idx = prev_insn_idx;
>  	elem->next = env->head;
> -	elem->log_pos = env->log.len_used;
> +	elem->log_pos = env->log.end_pos;
>  	env->head = elem;
>  	env->stack_size++;
>  	err = copy_verifier_state(&elem->st, cur);
> @@ -2282,7 +2282,7 @@ static struct bpf_verifier_state *push_async_cb(struct bpf_verifier_env *env,
>  	elem->insn_idx = insn_idx;
>  	elem->prev_insn_idx = prev_insn_idx;
>  	elem->next = env->head;
> -	elem->log_pos = env->log.len_used;
> +	elem->log_pos = env->log.end_pos;
>  	env->head = elem;
>  	env->stack_size++;
>  	if (env->stack_size > BPF_COMPLEXITY_LIMIT_JMP_SEQ) {
> @@ -15563,11 +15563,11 @@ static int do_check(struct bpf_verifier_env *env)
>  				print_insn_state(env, state->frame[state->curframe]);
>  
>  			verbose_linfo(env, env->insn_idx, "; ");
> -			env->prev_log_len = env->log.len_used;
> +			env->prev_log_pos = env->log.end_pos;
>  			verbose(env, "%d: ", env->insn_idx);
>  			print_bpf_insn(&cbs, insn, env->allow_ptr_leaks);
> -			env->prev_insn_print_len = env->log.len_used - env->prev_log_len;
> -			env->prev_log_len = env->log.len_used;
> +			env->prev_insn_print_pos = env->log.end_pos - env->prev_log_pos;
> +			env->prev_log_pos = env->log.end_pos;
>  		}
>  
>  		if (bpf_prog_is_offloaded(env->prog->aux)) {
> @@ -18780,6 +18780,7 @@ int bpf_check(struct bpf_prog **prog, union bpf_attr *attr, bpfptr_t uattr)
>  	print_verification_stats(env);
>  	env->prog->aux->verified_insns = env->insn_processed;
>  
> +	bpf_vlog_finalize(log);
>  	if (log->level && bpf_verifier_log_full(log))
>  		ret = -ENOSPC;
>  	if (log->level && !log->ubuf) {
> diff --git a/tools/testing/selftests/bpf/prog_tests/log_fixup.c b/tools/testing/selftests/bpf/prog_tests/log_fixup.c
> index 239e1c5753b0..bc27170bdeb0 100644
> --- a/tools/testing/selftests/bpf/prog_tests/log_fixup.c
> +++ b/tools/testing/selftests/bpf/prog_tests/log_fixup.c
> @@ -24,6 +24,7 @@ static void bad_core_relo(size_t log_buf_size, enum trunc_type trunc_type)
>  	bpf_program__set_autoload(skel->progs.bad_relo, true);
>  	memset(log_buf, 0, sizeof(log_buf));
>  	bpf_program__set_log_buf(skel->progs.bad_relo, log_buf, log_buf_size ?: sizeof(log_buf));
> +	bpf_program__set_log_level(skel->progs.bad_relo, 1 | 8); /* BPF_LOG_FIXED to force truncation */
>  
>  	err = test_log_fixup__load(skel);
>  	if (!ASSERT_ERR(err, "load_fail"))

Re: [PATCH bpf-next 3/6] bpf: switch BPF verifier log to be a rotating log by default

[Andrii Nakryiko]

On Thu, Mar 16, 2023 at 8:54 PM Alexei Starovoitov
<alexei.starovoitov@gmail.com> wrote:
>
> On Thu, Mar 16, 2023 at 11:30:10AM -0700, Andrii Nakryiko wrote:
> > Currently, if user-supplied log buffer to collect BPF verifier log turns
> > out to be too small to contain full log, bpf() syscall return -ENOSPC,
> > fails BPF program verification/load, but preserves first N-1 bytes of
> > verifier log (where N is the size of user-supplied buffer).
> >
> > This is problematic in a bunch of common scenarios, especially when
> > working with real-world BPF programs that tend to be pretty complex as
> > far as verification goes and require big log buffers. Typically, it's
> > when debugging tricky cases at log level 2 (verbose). Also, when BPF program
> > is successfully validated, log level 2 is the only way to actually see
> > verifier state progression and all the important details.
> >
> > Even with log level 1, it's possible to get -ENOSPC even if the final
> > verifier log fits in log buffer, if there is a code path that's deep
> > enough to fill up entire log, even if normally it would be reset later
> > on (there is a logic to chop off successfully validated portions of BPF
> > verifier log).
> >
> > In short, it's not always possible to pre-size log buffer. Also, in
> > practice, the end of the log most often is way more important than the
> > beginning.
> >
> > This patch switches BPF verifier log behavior to effectively behave as
> > rotating log. That is, if user-supplied log buffer turns out to be too
> > short, instead of failing with -ENOSPC, verifier will keep overwriting
> > previously written log, effectively treating user's log buffer as a ring
> > buffer.
> >
> > Importantly, though, to preserve good user experience and not require
> > every user-space application to adopt to this new behavior, before
> > exiting to user-space verifier will rotate log (in place) to make it
> > start at the very beginning of user buffer as a continuous
> > zero-terminated string. The contents will be a chopped off N-1 last
> > bytes of full verifier log, of course.
> >
> > Given beginning of log is sometimes important as well, we add
> > BPF_LOG_FIXED (which equals 8) flag to force old behavior, which allows
> > tools like veristat to request first part of verifier log, if necessary.
> >
> > On the implementation side, conceptually, it's all simple. We maintain
> > 64-bit logical start and end positions. If we need to truncate the log,
> > start position will be adjusted accordingly to lag end position by
> > N bytes. We then use those logical positions to calculate their matching
> > actual positions in user buffer and handle wrap around the end of the
> > buffer properly. Finally, right before returning from bpf_check(), we
> > rotate user log buffer contents in-place as necessary, to make log
> > contents contiguous. See comments in relevant functions for details.
> >
> > Signed-off-by: Andrii Nakryiko <andrii@kernel.org>
> > ---
> >  include/linux/bpf_verifier.h                  |  32 ++-
> >  kernel/bpf/log.c                              | 182 +++++++++++++++++-
> >  kernel/bpf/verifier.c                         |  17 +-
> >  .../selftests/bpf/prog_tests/log_fixup.c      |   1 +
> >  4 files changed, 209 insertions(+), 23 deletions(-)
> >
> > diff --git a/include/linux/bpf_verifier.h b/include/linux/bpf_verifier.h
> > index 83dff25545ee..cff11c99ed9a 100644
> > --- a/include/linux/bpf_verifier.h
> > +++ b/include/linux/bpf_verifier.h
> > @@ -491,25 +491,42 @@ struct bpf_insn_aux_data {
> >  #define BPF_VERIFIER_TMP_LOG_SIZE    1024
> >
> >  struct bpf_verifier_log {
> > -     u32 level;
> > -     char kbuf[BPF_VERIFIER_TMP_LOG_SIZE];
> > +     /* Logical start and end positions of a "log window" of the verifier log.
> > +      * start_pos == 0 means we haven't truncated anything.
> > +      * Once truncation starts to happen, start_pos + len_total == end_pos,
> > +      * except during log reset situations, in which (end_pos - start_pos)
> > +      * might get smaller than len_total (see bpf_vlog_reset()).
> > +      * Generally, (end_pos - start_pos) gives number of useful data in
> > +      * user log buffer.
> > +      */
> > +     u64 start_pos;
> > +     u64 end_pos;
> ...
> >
> > -void bpf_vlog_reset(struct bpf_verifier_log *log, u32 new_pos)
> > +void bpf_vlog_reset(struct bpf_verifier_log *log, u64 new_pos)
> >  {
> >       char zero = 0;
> >
> >       if (!bpf_verifier_log_needed(log))
> >               return;
> >
> > -     log->len_used = new_pos;
> > +     /* if position to which we reset is beyond current log window, then we
> > +      * didn't preserve any useful content and should adjust adjust
> > +      * start_pos to end up with an empty log (start_pos == end_pos)
> > +      */
> > +     log->end_pos = new_pos;
> > +     if (log->end_pos < log->start_pos)
> > +             log->start_pos = log->end_pos;
> > +
> >       if (put_user(zero, log->ubuf + new_pos))
>
> Haven't analyzed the code in details and asking based on comments...
> new_pos can be bigger than ubuf size and above write will be out of bounds, no?

Oh, great catch! Yes, new_pos is "logical position", so definitely can
go beyond buffer bounds. It should have been `log->ubuf + (new_pos %
log->len_total)`, of course. I'll improve tests to validate that the
buffer beyond allowed boundaries isn't modified at all, to catch this.

Re: [PATCH bpf-next 3/6] bpf: switch BPF verifier log to be a rotating log by default

[Andrii Nakryiko]

On Fri, Mar 17, 2023 at 8:05 AM Eduard Zingerman <eddyz87@gmail.com> wrote:
>
> On Thu, 2023-03-16 at 11:30 -0700, Andrii Nakryiko wrote:
> > Currently, if user-supplied log buffer to collect BPF verifier log turns
> > out to be too small to contain full log, bpf() syscall return -ENOSPC,
> > fails BPF program verification/load, but preserves first N-1 bytes of
> > verifier log (where N is the size of user-supplied buffer).
> >
> > This is problematic in a bunch of common scenarios, especially when
> > working with real-world BPF programs that tend to be pretty complex as
> > far as verification goes and require big log buffers. Typically, it's
> > when debugging tricky cases at log level 2 (verbose). Also, when BPF program
> > is successfully validated, log level 2 is the only way to actually see
> > verifier state progression and all the important details.
> >
> > Even with log level 1, it's possible to get -ENOSPC even if the final
> > verifier log fits in log buffer, if there is a code path that's deep
> > enough to fill up entire log, even if normally it would be reset later
> > on (there is a logic to chop off successfully validated portions of BPF
> > verifier log).
> >
> > In short, it's not always possible to pre-size log buffer. Also, in
> > practice, the end of the log most often is way more important than the
> > beginning.
> >
> > This patch switches BPF verifier log behavior to effectively behave as
> > rotating log. That is, if user-supplied log buffer turns out to be too
> > short, instead of failing with -ENOSPC, verifier will keep overwriting
> > previously written log, effectively treating user's log buffer as a ring
> > buffer.
> >
> > Importantly, though, to preserve good user experience and not require
> > every user-space application to adopt to this new behavior, before
> > exiting to user-space verifier will rotate log (in place) to make it
> > start at the very beginning of user buffer as a continuous
> > zero-terminated string. The contents will be a chopped off N-1 last
> > bytes of full verifier log, of course.
> >
> > Given beginning of log is sometimes important as well, we add
> > BPF_LOG_FIXED (which equals 8) flag to force old behavior, which allows
> > tools like veristat to request first part of verifier log, if necessary.
> >
> > On the implementation side, conceptually, it's all simple. We maintain
> > 64-bit logical start and end positions. If we need to truncate the log,
> > start position will be adjusted accordingly to lag end position by
> > N bytes. We then use those logical positions to calculate their matching
> > actual positions in user buffer and handle wrap around the end of the
> > buffer properly. Finally, right before returning from bpf_check(), we
> > rotate user log buffer contents in-place as necessary, to make log
> > contents contiguous. See comments in relevant functions for details.
> >
> > Signed-off-by: Andrii Nakryiko <andrii@kernel.org>
>
> I tried bpf_verifier_vlog() and bpf_vlog_finalize() using some
> randomized testing + valgrind and everything seems to be fine.

Thanks for additional testing!

> Tbh, it seems to me that having kunit tests for things like this might
> be a good idea.

I found that this user-space driven testing using variable log_buf
size causes all the different corner cases, so felt confident enough
that match is right.

I missed the issue that Alexei caught because it never went past
user-space buffer (those 1K bytes), so it was poking zeros in
unused/unchecked portion of user-provided buffer. I'll add explicit
test that that contents is not modified (probably will fill with some
character and check that nothing changed. Hopefully that will be
enough to prevent any such issues in the future.


>
> Test script for reference:
>
>   void once(char *in, size_t out_sz) {
>         struct bpf_verifier_log log = {};
>         char *out = calloc(out_sz, 1);
>         size_t in_sz = strlen(in);
>         size_t orig_out_sz = out_sz;
>
>         log.ubuf = out;
>         log.len_total = out_sz;
>         log.level = 1 | 2 | 4;
>
>         for (char *input = strtok(in, " "); input; input = strtok(NULL, " "))
>                 bpf_verifier_vlog(&log, input);
>
>         bpf_vlog_finalize(&log);
>
>         for (unsigned i = 0; i < in_sz; ++i)
>                 if (in[i] == 0)
>                         in[i] = ' ';
>
>         out_sz = strlen(out);
>         if (in_sz)
>                 --in_sz;
>         if (out_sz)
>                 --out_sz;
>         while (out_sz > 0 && in_sz > 0) {
>                 if (in[in_sz] == ' ') {
>                         --in_sz;
>                         continue;
>                 }
>                 if (in[in_sz] == out[out_sz]) {
>                         --in_sz;
>                         --out_sz;
>                         continue;
>                 }
>                 printf("    in: '%s'\n", in);
>                 printf("   out: '%s'\n", out);
>                 printf("err at: %lu\n", out_sz);
>                 printf("out_sz: %lu\n", orig_out_sz);
>                 break;
>         }
>
>         free(out);
>   }
>
>   void rnd_once() {
>         char in[1024] = {};
>         size_t out_sz = 1 + rand() % 100;
>         size_t in_sz = rand() % (sizeof(in) - 1);
>         int cnt = 0;
>
>         for (unsigned i = 0; i < in_sz; ++i)
>                 if (rand() % 100 < 7)
>                         in[i] = ' ';
>                 else
>                         in[i] = 'a' + (rand() % 26);
>
>         once(in, out_sz);
>   }
>
>   int main(int argc, char **argv) {
>         if (argc == 3) {
>                 once(argv[2], atoi(argv[1]));
>         } else {
>                 srand(clock());
>                 for (int i = 0; i < 100000; ++i)
>                         rnd_once();
>         }
>   }
>
> Tested-by: Eduard Zingerman <eddyz87@gmail.com>
>
> > ---
> >  include/linux/bpf_verifier.h                  |  32 ++-
> >  kernel/bpf/log.c                              | 182 +++++++++++++++++-
> >  kernel/bpf/verifier.c                         |  17 +-
> >  .../selftests/bpf/prog_tests/log_fixup.c      |   1 +
> >  4 files changed, 209 insertions(+), 23 deletions(-)
> >

[...]

[PATCH bpf-next 4/6] libbpf: don't enfore verifier log levels on libbpf side

[Andrii Nakryiko]

This basically prevents any forward compatibility. And we either way
just return -EINVAL, which would otherwise be returned from bpf()
syscall anyways.

Signed-off-by: Andrii Nakryiko <andrii@kernel.org>
---
 tools/lib/bpf/bpf.c | 2 --
 1 file changed, 2 deletions(-)

diff --git a/tools/lib/bpf/bpf.c b/tools/lib/bpf/bpf.c
index e750b6f5fcc3..eb08a998b526 100644
--- a/tools/lib/bpf/bpf.c
+++ b/tools/lib/bpf/bpf.c
@@ -290,8 +290,6 @@ int bpf_prog_load(enum bpf_prog_type prog_type,
 
 	if (!!log_buf != !!log_size)
 		return libbpf_err(-EINVAL);
-	if (log_level > (4 | 2 | 1))
-		return libbpf_err(-EINVAL);
 	if (log_level && !log_buf)
 		return libbpf_err(-EINVAL);
 
-- 
2.34.1

[PATCH bpf-next 4/6] libbpf: don't enfore verifier log levels on libbpf side

[Andrii Nakryiko]

This basically prevents any forward compatibility. And we either way
just return -EINVAL, which would otherwise be returned from bpf()
syscall anyways.

Signed-off-by: Andrii Nakryiko <andrii@kernel.org>
---
 tools/lib/bpf/bpf.c | 2 --
 1 file changed, 2 deletions(-)

diff --git a/tools/lib/bpf/bpf.c b/tools/lib/bpf/bpf.c
index e750b6f5fcc3..eb08a998b526 100644
--- a/tools/lib/bpf/bpf.c
+++ b/tools/lib/bpf/bpf.c
@@ -290,8 +290,6 @@ int bpf_prog_load(enum bpf_prog_type prog_type,
 
 	if (!!log_buf != !!log_size)
 		return libbpf_err(-EINVAL);
-	if (log_level > (4 | 2 | 1))
-		return libbpf_err(-EINVAL);
 	if (log_level && !log_buf)
 		return libbpf_err(-EINVAL);
 
-- 
2.34.1