* [PATCH bpf-next 1/6] bpf: split off basic BPF verifier log into separate file
2023-03-17 22:03 [PATCH bpf-next 0/6] BPF verifier rotating log Andrii Nakryiko
@ 2023-03-17 22:03 ` Andrii Nakryiko
2023-03-17 22:03 ` [PATCH bpf-next 2/6] bpf: remove minimum size restrictions on verifier log buffer Andrii Nakryiko
` (4 subsequent siblings)
5 siblings, 0 replies; 16+ messages in thread
From: Andrii Nakryiko @ 2023-03-17 22:03 UTC (permalink / raw)
To: bpf, ast, daniel, martin.lau; +Cc: andrii, kernel-team
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 99394a2f7ee4..48b7809c429f 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
^ permalink raw reply related [flat|nested] 16+ messages in thread
* [PATCH bpf-next 2/6] bpf: remove minimum size restrictions on verifier log buffer
2023-03-17 22:03 [PATCH bpf-next 0/6] BPF verifier rotating log Andrii Nakryiko
2023-03-17 22:03 ` [PATCH bpf-next 1/6] bpf: split off basic BPF verifier log into separate file Andrii Nakryiko
@ 2023-03-17 22:03 ` Andrii Nakryiko
2023-03-17 22:03 ` [PATCH bpf-next 3/6] bpf: switch BPF verifier log to be a rotating log by default Andrii Nakryiko
` (3 subsequent siblings)
5 siblings, 0 replies; 16+ messages in thread
From: Andrii Nakryiko @ 2023-03-17 22:03 UTC (permalink / raw)
To: bpf, ast, daniel, martin.lau; +Cc: andrii, kernel-team
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
^ permalink raw reply related [flat|nested] 16+ messages in thread
* [PATCH bpf-next 3/6] bpf: switch BPF verifier log to be a rotating log by default
2023-03-17 22:03 [PATCH bpf-next 0/6] BPF verifier rotating log Andrii Nakryiko
2023-03-17 22:03 ` [PATCH bpf-next 1/6] bpf: split off basic BPF verifier log into separate file Andrii Nakryiko
2023-03-17 22:03 ` [PATCH bpf-next 2/6] bpf: remove minimum size restrictions on verifier log buffer Andrii Nakryiko
@ 2023-03-17 22:03 ` Andrii Nakryiko
2023-03-17 22:05 ` Andrii Nakryiko
2023-03-17 23:02 ` Daniel Borkmann
2023-03-17 22:03 ` [PATCH bpf-next 4/6] libbpf: don't enfore verifier log levels on libbpf side Andrii Nakryiko
` (2 subsequent siblings)
5 siblings, 2 replies; 16+ messages in thread
From: Andrii Nakryiko @ 2023-03-17 22:03 UTC (permalink / raw)
To: bpf, ast, daniel, martin.lau; +Cc: andrii, kernel-team
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 | 187 +++++++++++++++++-
kernel/bpf/verifier.c | 17 +-
.../selftests/bpf/prog_tests/log_fixup.c | 1 +
4 files changed, 213 insertions(+), 24 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..c4a47862c1cd 100644
--- a/kernel/bpf/log.c
+++ b/kernel/bpf/log.c
@@ -8,6 +8,7 @@
#include <linux/types.h>
#include <linux/bpf.h>
#include <linux/bpf_verifier.h>
+#include <linux/math64.h>
bool bpf_verifier_log_attr_valid(const struct bpf_verifier_log *log)
{
@@ -32,23 +33,191 @@ 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;
+
+ div_u64_rem(cur_pos, log->len_total, &buf_start);
+ div_u64_rem(new_end, log->len_total, &buf_end);
+ /* 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;
+ u32 pos;
if (!bpf_verifier_log_needed(log))
return;
- log->len_used = new_pos;
- if (put_user(zero, log->ubuf + new_pos))
+ /* if position to which we reset is beyond current log window,
+ * then we didn't preserve any useful content and should 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;
+ div_u64_rem(new_pos, log->len_total, &pos);
+ if (put_user(zero, log->ubuf + 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
+ */
+ div_u64_rem(log->start_pos, log->len_total, &sublen);
+ sublen = log->len_total - sublen;
+
+ 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;
}
diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
index 48b7809c429f..391bbb3b2274 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) {
@@ -15560,11 +15560,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)) {
@@ -18777,6 +18777,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
^ permalink raw reply related [flat|nested] 16+ messages in thread
* Re: [PATCH bpf-next 3/6] bpf: switch BPF verifier log to be a rotating log by default
2023-03-17 22:03 ` [PATCH bpf-next 3/6] bpf: switch BPF verifier log to be a rotating log by default Andrii Nakryiko
@ 2023-03-17 22:05 ` Andrii Nakryiko
2023-03-17 23:02 ` Daniel Borkmann
1 sibling, 0 replies; 16+ messages in thread
From: Andrii Nakryiko @ 2023-03-17 22:05 UTC (permalink / raw)
To: Andrii Nakryiko; +Cc: bpf, ast, daniel, martin.lau, kernel-team
On Fri, Mar 17, 2023 at 3:04 PM Andrii Nakryiko <andrii@kernel.org> 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>
> ---
forgot to carry over Eduard's Tested-by:
Tested-by: Eduard Zingerman <eddyz87@gmail.com>
> include/linux/bpf_verifier.h | 32 ++-
> kernel/bpf/log.c | 187 +++++++++++++++++-
> kernel/bpf/verifier.c | 17 +-
> .../selftests/bpf/prog_tests/log_fixup.c | 1 +
> 4 files changed, 213 insertions(+), 24 deletions(-)
>
[...]
^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: [PATCH bpf-next 3/6] bpf: switch BPF verifier log to be a rotating log by default
2023-03-17 22:03 ` [PATCH bpf-next 3/6] bpf: switch BPF verifier log to be a rotating log by default Andrii Nakryiko
2023-03-17 22:05 ` Andrii Nakryiko
@ 2023-03-17 23:02 ` Daniel Borkmann
2023-03-17 23:12 ` Andrii Nakryiko
1 sibling, 1 reply; 16+ messages in thread
From: Daniel Borkmann @ 2023-03-17 23:02 UTC (permalink / raw)
To: Andrii Nakryiko, bpf, ast, martin.lau; +Cc: kernel-team, i, timo
On 3/17/23 11:03 PM, 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>
Did you check behavior with other loaders if changing default works ok
for them, e.g. their behavior/buffer around ENOSPC handling for growing?
The go loader library did some parsing around the log [0], adding Lorenz
and Timo for Cc for checking.
[0] https://github.com/cilium/ebpf/blob/master/internal/errors.go
https://github.com/cilium/ebpf/blob/master/prog.go#L61
^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: [PATCH bpf-next 3/6] bpf: switch BPF verifier log to be a rotating log by default
2023-03-17 23:02 ` Daniel Borkmann
@ 2023-03-17 23:12 ` Andrii Nakryiko
2023-03-20 16:10 ` Lorenz Bauer
0 siblings, 1 reply; 16+ messages in thread
From: Andrii Nakryiko @ 2023-03-17 23:12 UTC (permalink / raw)
To: Daniel Borkmann
Cc: Andrii Nakryiko, bpf, ast, martin.lau, kernel-team, i, timo,
alessandro.d, Dave Tucker
On Fri, Mar 17, 2023 at 4:02 PM Daniel Borkmann <daniel@iogearbox.net> wrote:
>
> On 3/17/23 11:03 PM, 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>
>
> Did you check behavior with other loaders if changing default works ok
> for them, e.g. their behavior/buffer around ENOSPC handling for growing?
>
> The go loader library did some parsing around the log [0], adding Lorenz
> and Timo for Cc for checking.
I didn't, no. Thanks for pinging Lorenz and Timo.
Libbpf by default uses 16MB right now, I didn't touch that part yet,
but it might be good to reduce this size if the kernel supports this
new behavior. Go library seems to be using 64KB, which probably would
be adequate for a lot of cases, but yeah, maybe Go library would like
to use slightly bigger default if rotating log behavior is supported
by kernel?
Alternative would be to make this rotating behavior opt-in, but that
would require active actions by multiple libraries and applications to
actively detect support. Given the rotating behavior seems like a good
default behavior I wish we had from the very beginning, I went for
making it default.
Let's see what Lorenz and Timo think.
Adding also aya-rs main contributors (Allesandro and Dave). Seems like
aya-rs uses very small 10KB minimum log buf size, which might be a bit
inadequate with rotating log semantics.
>
> [0] https://github.com/cilium/ebpf/blob/master/internal/errors.go
> https://github.com/cilium/ebpf/blob/master/prog.go#L61
^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: [PATCH bpf-next 3/6] bpf: switch BPF verifier log to be a rotating log by default
2023-03-17 23:12 ` Andrii Nakryiko
@ 2023-03-20 16:10 ` Lorenz Bauer
2023-03-20 18:55 ` Andrii Nakryiko
0 siblings, 1 reply; 16+ messages in thread
From: Lorenz Bauer @ 2023-03-20 16:10 UTC (permalink / raw)
To: Andrii Nakryiko
Cc: Daniel Borkmann, Andrii Nakryiko, bpf, ast, martin.lau,
kernel-team, i, timo, alessandro.d, Dave Tucker,
Robin Gögge
Hi Andrii!
This is a great idea. Preserving the end of the log is the right thing
to do, and I agree that it would've been nice to do this from the
start. Some thoughts on the approach below, based on a discussion I
had with Robin and Timo.
On Fri, Mar 17, 2023 at 11:13 PM Andrii Nakryiko
<andrii.nakryiko@gmail.com> wrote:
>
> Libbpf by default uses 16MB right now, I didn't touch that part yet,
> but it might be good to reduce this size if the kernel supports this
> new behavior. Go library seems to be using 64KB, which probably would
> be adequate for a lot of cases, but yeah, maybe Go library would like
> to use slightly bigger default if rotating log behavior is supported
> by kernel?
cilium/ebpf relies on ENOSPC to figure out if the verifier log has
been truncated, and makes that information available in the API via
VerifierError.Truncated [0]. This happens so that cilium can retry the
program load with successively larger log buffers to capture the full
verifier log. The full log is very valuable to us since we don't
operate on our own infrastructure, so reproducing an error that a
customer has on our own hardware is not always straightforward.
Instead we include the full log in sysdumps. We want to preserve this
as much as possible.
Arguably 64KB might already be on the large side! The library
currently does the "execute PROG_LOAD with log disabled first, get
debug output later" trick (which libbpf also does I think?). It'd be
nice if we could right-size the buffer on the retry.
> Alternative would be to make this rotating behavior opt-in, but that
> would require active actions by multiple libraries and applications to
> actively detect support. Given the rotating behavior seems like a good
> default behavior I wish we had from the very beginning, I went for
> making it default.
Given the above, taking away ENOSPC is problematic because an old
cilium/ebpf on a new kernel doesn't know how to get the full log. I
think it's better to make this opt in, since it also makes it easier
to reason about from user space. Working with UAPI that changes
behaviour based on kernel version is harder than doing feature
probing.
I do agree that ENOSPC is not a great API however and that it doesn't
make sense for the rotated log to return it. It's a really big hammer
that doesn't actually give us a key bit of information: how big should
the buffer have been to obtain the full log. To recap, cilium/ebpf
needs to know when the log was truncated and would like to know how
big the buffer should be. How about the following:
- To avoid breaking old libs on new kernels we make the behaviour opt
in via BPF_LOG_TRUNCATE_HEAD or similar.
- We add a field log_size_full to bpf_attr for PROG_LOAD. In the
kernel we populate it with the buffer size that is required to
retrieve an untruncated log for the given flags. log_size_full must be
0 when entering the syscall.
- If BPF_LOG_TRUNCATE_HEAD is specified, we enable rotation and never
return ENOSPC.
From the user space side, we can use the API as follows:
- If errno = ENOSPC or log_size < log_size_full we can deduce that the
log was truncated.
- If log_size_full > 0, we can use it to right-size the log buffer and
retry only once instead of the increase-buf-size-and-retry loop.
FWIW, BTF_LOAD would benefit from the same improvements!
Best
Lorenz
0: https://pkg.go.dev/github.com/cilium/ebpf@v0.10.0/internal#VerifierError
^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: [PATCH bpf-next 3/6] bpf: switch BPF verifier log to be a rotating log by default
2023-03-20 16:10 ` Lorenz Bauer
@ 2023-03-20 18:55 ` Andrii Nakryiko
2023-03-21 16:18 ` Lorenz Bauer
0 siblings, 1 reply; 16+ messages in thread
From: Andrii Nakryiko @ 2023-03-20 18:55 UTC (permalink / raw)
To: Lorenz Bauer
Cc: Daniel Borkmann, Andrii Nakryiko, bpf, ast, martin.lau,
kernel-team, i, timo, alessandro.d, Dave Tucker,
Robin Gögge
On Mon, Mar 20, 2023 at 9:10 AM Lorenz Bauer <lmb@isovalent.com> wrote:
>
> Hi Andrii!
>
> This is a great idea. Preserving the end of the log is the right thing
> to do, and I agree that it would've been nice to do this from the
> start. Some thoughts on the approach below, based on a discussion I
> had with Robin and Timo.
>
> On Fri, Mar 17, 2023 at 11:13 PM Andrii Nakryiko
> <andrii.nakryiko@gmail.com> wrote:
> >
> > Libbpf by default uses 16MB right now, I didn't touch that part yet,
> > but it might be good to reduce this size if the kernel supports this
> > new behavior. Go library seems to be using 64KB, which probably would
> > be adequate for a lot of cases, but yeah, maybe Go library would like
> > to use slightly bigger default if rotating log behavior is supported
> > by kernel?
>
> cilium/ebpf relies on ENOSPC to figure out if the verifier log has
> been truncated, and makes that information available in the API via
> VerifierError.Truncated [0]. This happens so that cilium can retry the
> program load with successively larger log buffers to capture the full
> verifier log. The full log is very valuable to us since we don't
> operate on our own infrastructure, so reproducing an error that a
> customer has on our own hardware is not always straightforward.
> Instead we include the full log in sysdumps. We want to preserve this
> as much as possible.
>
> Arguably 64KB might already be on the large side! The library
> currently does the "execute PROG_LOAD with log disabled first, get
> debug output later" trick (which libbpf also does I think?). It'd be
> nice if we could right-size the buffer on the retry.
>
> > Alternative would be to make this rotating behavior opt-in, but that
> > would require active actions by multiple libraries and applications to
> > actively detect support. Given the rotating behavior seems like a good
> > default behavior I wish we had from the very beginning, I went for
> > making it default.
>
> Given the above, taking away ENOSPC is problematic because an old
> cilium/ebpf on a new kernel doesn't know how to get the full log. I
> think it's better to make this opt in, since it also makes it easier
> to reason about from user space. Working with UAPI that changes
> behaviour based on kernel version is harder than doing feature
> probing.
>
> I do agree that ENOSPC is not a great API however and that it doesn't
> make sense for the rotated log to return it. It's a really big hammer
> that doesn't actually give us a key bit of information: how big should
> the buffer have been to obtain the full log. To recap, cilium/ebpf
> needs to know when the log was truncated and would like to know how
> big the buffer should be. How about the following:
>
> - To avoid breaking old libs on new kernels we make the behaviour opt
> in via BPF_LOG_TRUNCATE_HEAD or similar.
> - We add a field log_size_full to bpf_attr for PROG_LOAD. In the
> kernel we populate it with the buffer size that is required to
> retrieve an untruncated log for the given flags. log_size_full must be
> 0 when entering the syscall.
> - If BPF_LOG_TRUNCATE_HEAD is specified, we enable rotation and never
> return ENOSPC.
>
> From the user space side, we can use the API as follows:
>
> - If errno = ENOSPC or log_size < log_size_full we can deduce that the
> log was truncated.
> - If log_size_full > 0, we can use it to right-size the log buffer and
> retry only once instead of the increase-buf-size-and-retry loop.
>
Great feedback. Let me address all of it in one place.
Let's start with right-sizing the buffer. Curiously, with existing
(fixed) log behavior, verifier doesn't and can't know the full size of
the buffer it needs, as we stop producing log after -ENOSPC condition
was detected. log->ubuf is set to NULL, after which
bpf_verifier_log_needed() will start returning false. So in existing
"logging mode" it's impossible to support this without major changes.
On the other hand, with rotating log, we could determine this very
easily! We can just maintain max(log->end_pos, last_max_end_pos)
throughout the verification process (we need max due to log reset: it
still might need bigger buffer than final log length).
So, to get the full size, we need rotating log behavior.
What if we just make rotating log still return -ENOSPC, and set this
new "log_buf_max_size" field to actual required full size. That will
keep existing retry/resize logic intact and would be backwards
compatible, right?
As for feature detecting this change. Yes, there is no UAPI change
(unless we add extra field, of course), but as I implemented it right
now it's trivial to detect the change in behavior: set small buffer
(few bytes), try load trivial program. If you get -EINVAL, then we
have old kernel that enforces >=128 bytes for buffer. If you specify a
bit bigger buffer, you should get -ENOSPC. If you get success, it's
the new behavior.
So feature detection is not hard for library.
What I'm worried with switching this to opt-in
(BPF_LOG_TRUNCATE_HEAD), is that for various application that would
want to use log_level 1/2 for some diagnostics in runtime, *they*
would need to perform this feature detection just to know that it's
safe to provide BPF_LOG_TRUNCATE_HEAD. So I decided that it's better
use experience to do opt-out. Just to explain my reasoning, I wanted
to make users not care about this and just get useful log back.
But in summary, what do you think about just returning -ENOSPC even
with new behavior and keep rotating log behavior default?
Additionally, for rotating mode we can return required max log buffer
size in a new UAPI field.
Would this address all your concerns?
> FWIW, BTF_LOAD would benefit from the same improvements!
Heh, it actually does automatically as it uses bpf_verifier_log struct
as well. So all the BPF_PROG_LOAD changes for log apply to BPF_BTF_LOG
command.
>
> Best
> Lorenz
>
> 0: https://pkg.go.dev/github.com/cilium/ebpf@v0.10.0/internal#VerifierError
^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: [PATCH bpf-next 3/6] bpf: switch BPF verifier log to be a rotating log by default
2023-03-20 18:55 ` Andrii Nakryiko
@ 2023-03-21 16:18 ` Lorenz Bauer
2023-03-22 21:27 ` Andrii Nakryiko
0 siblings, 1 reply; 16+ messages in thread
From: Lorenz Bauer @ 2023-03-21 16:18 UTC (permalink / raw)
To: Andrii Nakryiko
Cc: Daniel Borkmann, Andrii Nakryiko, bpf, ast, martin.lau,
kernel-team, timo, alessandro.d, Dave Tucker, Robin Gögge
On Mon, Mar 20, 2023 at 6:55 PM Andrii Nakryiko
<andrii.nakryiko@gmail.com> wrote:
>
> Great feedback. Let me address all of it in one place.
>
> Let's start with right-sizing the buffer. Curiously, with existing
> (fixed) log behavior, verifier doesn't and can't know the full size of
> the buffer it needs, as we stop producing log after -ENOSPC condition
> was detected. log->ubuf is set to NULL, after which
> bpf_verifier_log_needed() will start returning false. So in existing
> "logging mode" it's impossible to support this without major changes.
I think that's fine, as long as we keep the door open to later on
extending the log_buf_max_size to append mode.
> On the other hand, with rotating log, we could determine this very
> easily! We can just maintain max(log->end_pos, last_max_end_pos)
> throughout the verification process (we need max due to log reset: it
> still might need bigger buffer than final log length).
Ah, tricky! Nitty gritty detail: can I get the max required size with
log_level > 0 but log_buf == NULL / log_size == 0?
> So, to get the full size, we need rotating log behavior.
>
> What if we just make rotating log still return -ENOSPC, and set this
> new "log_buf_max_size" field to actual required full size. That will
> keep existing retry/resize logic intact and would be backwards
> compatible, right?
There is a subtlety here: with this design it's impossible to load a
program with a rotating log and a buffer that is smaller than
log_buf_max_size. A contrived use case: for each program we load we'd
like to get the verifier stats printed as one of the last lines.
Without ENOSPC this can be done by allocating a buffer of 512 bytes or
something.
Tying errno to log buffer size is wrong imo, so it'd be nice if we
could fix the interface going forward.
> As for feature detecting this change. Yes, there is no UAPI change
> (unless we add extra field, of course), but as I implemented it right
> now it's trivial to detect the change in behavior: set small buffer
> (few bytes), try load trivial program. If you get -EINVAL, then we
> have old kernel that enforces >=128 bytes for buffer. If you specify a
> bit bigger buffer, you should get -ENOSPC. If you get success, it's
> the new behavior.
I think a better test would actually be to pass the new BPF_LOG flag
and check for EINVAL. Relying on buffer sizes is maybe a bit too
indirect?
> What I'm worried with switching this to opt-in
> (BPF_LOG_TRUNCATE_HEAD), is that for various application that would
> want to use log_level 1/2 for some diagnostics in runtime, *they*
> would need to perform this feature detection just to know that it's
> safe to provide BPF_LOG_TRUNCATE_HEAD.
Can you sketch this out a bit more, what kind of diagnostics do you
have in mind? If the application wants to parse the log it kind of
needs to know anyways? Going back to my "get verifier stats from prog
load" example above, if the rotating log isn't available I need to
either
- skip getting verifier stats
- allocate a possibly large buffer to get at it in append mode
That choice isn't one I can make as a library author.
> So I decided that it's better
> use experience to do opt-out. Just to explain my reasoning, I wanted
> to make users not care about this and just get useful log back.
Ah, this is probably where our disconnect is. In my mind, detecting
and passing BPF_LOG_TRUNCATE_HEAD is definitely the responsibility of
the library, not the users. At least for the happy / common path.
Rough sketch of how PROG_LOAD and log_buf is handled in Go (probably
similar to libbpf?)
if PROG_LOAD(user supplied log_level) < 0 && user supplied log_level == 0:
retry PROG_LOAD(log_level=1)
There is some trickery when the user passes a log_level != 0, but most
PROG_LOAD go through this logic. The way I'd go about it is to add
TRUNCATE_HEAD to the retry PROG_LOAD call if the feature exists. As a
result, most failed program loads would get the benefit of this
feature.
If a user explicitly requests a log I assume they know what they are
doing and it's probably best not to mess with it. To play the devil's
advocate, I think that making this behaviour opt out does break
expectations that user space has. See [0] for example which will have
to detect that rotating mode is used and deliberately disable that. We
can of course argue whether parsing the log is a wise thing to do, but
it's good to keep that fact in mind.
> Heh, it actually does automatically as it uses bpf_verifier_log struct
> as well. So all the BPF_PROG_LOAD changes for log apply to BPF_BTF_LOG
> command.
Nice :)
Best
Lorenz
0: https://github.com/cilium/coverbee
^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: [PATCH bpf-next 3/6] bpf: switch BPF verifier log to be a rotating log by default
2023-03-21 16:18 ` Lorenz Bauer
@ 2023-03-22 21:27 ` Andrii Nakryiko
0 siblings, 0 replies; 16+ messages in thread
From: Andrii Nakryiko @ 2023-03-22 21:27 UTC (permalink / raw)
To: Lorenz Bauer
Cc: Daniel Borkmann, Andrii Nakryiko, bpf, ast, martin.lau,
kernel-team, timo, alessandro.d, Dave Tucker, Robin Gögge
On Tue, Mar 21, 2023 at 9:18 AM Lorenz Bauer <lmb@isovalent.com> wrote:
>
> On Mon, Mar 20, 2023 at 6:55 PM Andrii Nakryiko
> <andrii.nakryiko@gmail.com> wrote:
> >
> > Great feedback. Let me address all of it in one place.
> >
> > Let's start with right-sizing the buffer. Curiously, with existing
> > (fixed) log behavior, verifier doesn't and can't know the full size of
> > the buffer it needs, as we stop producing log after -ENOSPC condition
> > was detected. log->ubuf is set to NULL, after which
> > bpf_verifier_log_needed() will start returning false. So in existing
> > "logging mode" it's impossible to support this without major changes.
>
> I think that's fine, as long as we keep the door open to later on
> extending the log_buf_max_size to append mode.
Sure.
>
> > On the other hand, with rotating log, we could determine this very
> > easily! We can just maintain max(log->end_pos, last_max_end_pos)
> > throughout the verification process (we need max due to log reset: it
> > still might need bigger buffer than final log length).
>
> Ah, tricky! Nitty gritty detail: can I get the max required size with
> log_level > 0 but log_buf == NULL / log_size == 0?
See above about ubuf==NULL ignoring any log calls, so no. And
currently specifying log_level without specifying log_buf/log_size is
-EINVAL.
>
> > So, to get the full size, we need rotating log behavior.
> >
> > What if we just make rotating log still return -ENOSPC, and set this
> > new "log_buf_max_size" field to actual required full size. That will
> > keep existing retry/resize logic intact and would be backwards
> > compatible, right?
>
> There is a subtlety here: with this design it's impossible to load a
> program with a rotating log and a buffer that is smaller than
> log_buf_max_size. A contrived use case: for each program we load we'd
> like to get the verifier stats printed as one of the last lines.
> Without ENOSPC this can be done by allocating a buffer of 512 bytes or
> something.
You can do this with -ENOSPC as well. log_level = 4 will not emit lots
of data or require big buffer, verifier will just print out few lines
of log. So I think this case is covered just fine.
>
> Tying errno to log buffer size is wrong imo, so it'd be nice if we
> could fix the interface going forward.
You are nitpicking a bit here :) What I'd do in practice would be to
set a buffer to 128 bytes (minimum size allowed before my changes)
requested log_level=2 and would have guaranteed -ENOSPC. E.g. for
empty program that just returns 0, I get (with log_level 2):
0: R1=ctx(off=0,imm=0) R10=fp0
0: (b4) w0 = 0 ; R0_w=0
1: (95) exit
verification time 210 usec
stack depth 0
processed 2 insns (limit 1000000) max_states_per_insn 0 total_states 0
peak_states 0 mark_read 0
Which is 210 bytes. So practically speaking there is no issue at all.
But as you mentioned below, passing BPF_LOG_FIXED and expecting
-EINVAL is straightforward as well.
>
> > As for feature detecting this change. Yes, there is no UAPI change
> > (unless we add extra field, of course), but as I implemented it right
> > now it's trivial to detect the change in behavior: set small buffer
> > (few bytes), try load trivial program. If you get -EINVAL, then we
> > have old kernel that enforces >=128 bytes for buffer. If you specify a
> > bit bigger buffer, you should get -ENOSPC. If you get success, it's
> > the new behavior.
>
> I think a better test would actually be to pass the new BPF_LOG flag
> and check for EINVAL. Relying on buffer sizes is maybe a bit too
> indirect?
Sure, send BPF_LOG_FIXED and expect -EINVAL. Simple and works
reliably. So I guess I'd do that.
>
> > What I'm worried with switching this to opt-in
> > (BPF_LOG_TRUNCATE_HEAD), is that for various application that would
> > want to use log_level 1/2 for some diagnostics in runtime, *they*
> > would need to perform this feature detection just to know that it's
> > safe to provide BPF_LOG_TRUNCATE_HEAD.
>
> Can you sketch this out a bit more, what kind of diagnostics do you
> have in mind? If the application wants to parse the log it kind of
> needs to know anyways? Going back to my "get verifier stats from prog
> load" example above, if the rotating log isn't available I need to
> either
>
> - skip getting verifier stats
> - allocate a possibly large buffer to get at it in append mode
>
> That choice isn't one I can make as a library author.
See above, if you want only verifier stats, log_level=4 is the way to
go. It's guaranteed to fit in 512 buffer, so I don't think there is
any issue here.
As for user needing to feature-detect BPF_LOG_FIXED vs rotating log.
Libbpf provides ability to set custom buffer and log_level per program
or per entire BPF object, and libbpf passes this through to kernel. If
user wants rotating log and it's opt-in, then they would need to do
explicit feature detection, because libbpf can't guess user's intent.
Similarly, tools like veristat, they'd need to do their detection.
But we all agree that as a default, tail of the too long verifier log
is desirable default behavior. So I think it's worth fighting for
smooth experience, provided we don't break any reasonable application.
>
> > So I decided that it's better
> > use experience to do opt-out. Just to explain my reasoning, I wanted
> > to make users not care about this and just get useful log back.
>
> Ah, this is probably where our disconnect is. In my mind, detecting
> and passing BPF_LOG_TRUNCATE_HEAD is definitely the responsibility of
> the library, not the users. At least for the happy / common path.
> Rough sketch of how PROG_LOAD and log_buf is handled in Go (probably
> similar to libbpf?)
>
> if PROG_LOAD(user supplied log_level) < 0 && user supplied log_level == 0:
> retry PROG_LOAD(log_level=1)
>
> There is some trickery when the user passes a log_level != 0, but most
> PROG_LOAD go through this logic. The way I'd go about it is to add
> TRUNCATE_HEAD to the retry PROG_LOAD call if the feature exists. As a
> result, most failed program loads would get the benefit of this
> feature.
Right, this is not a big deal for libbpf and other loader libraries
for default "retry with log_level=1 if program load failed". But I'm
hoping we can get good default behavior for any other application to
get reasonable output when they provide their custom log_level and/or
log buffer.
>
> If a user explicitly requests a log I assume they know what they are
> doing and it's probably best not to mess with it. To play the devil's
> advocate, I think that making this behaviour opt out does break
> expectations that user space has. See [0] for example which will have
> to detect that rotating mode is used and deliberately disable that. We
> can of course argue whether parsing the log is a wise thing to do, but
> it's good to keep that fact in mind.
I'm not familiar with coverbee, which specific part will break due to
rotating vs fixed verifier log, assuming both return -ENOSPC?
CoverBee seems to be parsing verifier log and trying to make sense out
it (I see parsing register state, etc), so that tool definitely
expects that it would have to follow any verifier log format changes
and would have to accommodate them.
>
> > Heh, it actually does automatically as it uses bpf_verifier_log struct
> > as well. So all the BPF_PROG_LOAD changes for log apply to BPF_BTF_LOG
> > command.
>
> Nice :)
Yep.
So, in short, it still seems like -ENOSPC and rotating log behavior
covers all reasonable cases, except some specialized tools that
heavily rely on getting strictly head part of verifier log on -ENOSPC.
I do think providing needed log buffer size is a nice feature and will
add it in the next revision.
Please let me know if I addressed your concerns above (e.g.,
log_level=4 for verifier stats, etc)?
>
> Best
> Lorenz
>
> 0: https://github.com/cilium/coverbee
^ permalink raw reply [flat|nested] 16+ messages in thread
* [PATCH bpf-next 4/6] libbpf: don't enfore verifier log levels on libbpf side
2023-03-17 22:03 [PATCH bpf-next 0/6] BPF verifier rotating log Andrii Nakryiko
` (2 preceding siblings ...)
2023-03-17 22:03 ` [PATCH bpf-next 3/6] bpf: switch BPF verifier log to be a rotating log by default Andrii Nakryiko
@ 2023-03-17 22:03 ` Andrii Nakryiko
2023-03-17 22:03 ` [PATCH bpf-next 5/6] selftests/bpf: add more veristat control over verifier log options Andrii Nakryiko
2023-03-17 22:03 ` [PATCH bpf-next 6/6] selftests/bpf: add fixed vs rotating verifier log tests Andrii Nakryiko
5 siblings, 0 replies; 16+ messages in thread
From: Andrii Nakryiko @ 2023-03-17 22:03 UTC (permalink / raw)
To: bpf, ast, daniel, martin.lau; +Cc: andrii, kernel-team
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
^ permalink raw reply related [flat|nested] 16+ messages in thread
* [PATCH bpf-next 5/6] selftests/bpf: add more veristat control over verifier log options
2023-03-17 22:03 [PATCH bpf-next 0/6] BPF verifier rotating log Andrii Nakryiko
` (3 preceding siblings ...)
2023-03-17 22:03 ` [PATCH bpf-next 4/6] libbpf: don't enfore verifier log levels on libbpf side Andrii Nakryiko
@ 2023-03-17 22:03 ` Andrii Nakryiko
2023-03-17 22:03 ` [PATCH bpf-next 6/6] selftests/bpf: add fixed vs rotating verifier log tests Andrii Nakryiko
5 siblings, 0 replies; 16+ messages in thread
From: Andrii Nakryiko @ 2023-03-17 22:03 UTC (permalink / raw)
To: bpf, ast, daniel, martin.lau; +Cc: andrii, kernel-team
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
^ permalink raw reply related [flat|nested] 16+ messages in thread
* [PATCH bpf-next 6/6] selftests/bpf: add fixed vs rotating verifier log tests
2023-03-17 22:03 [PATCH bpf-next 0/6] BPF verifier rotating log Andrii Nakryiko
` (4 preceding siblings ...)
2023-03-17 22:03 ` [PATCH bpf-next 5/6] selftests/bpf: add more veristat control over verifier log options Andrii Nakryiko
@ 2023-03-17 22:03 ` Andrii Nakryiko
5 siblings, 0 replies; 16+ messages in thread
From: Andrii Nakryiko @ 2023-03-17 22:03 UTC (permalink / raw)
To: bpf, ast, daniel, martin.lau; +Cc: andrii, kernel-team
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 | 156 ++++++++++++++++++
1 file changed, 156 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..3c5cdf257014
--- /dev/null
+++ b/tools/testing/selftests/bpf/prog_tests/verifier_log.c
@@ -0,0 +1,156 @@
+// 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"
+
+
+static bool check_prog_load(int prog_fd, bool expect_err, const char *tag)
+{
+ if (expect_err) {
+ if (!ASSERT_LT(prog_fd, 0, tag)) {
+ close(prog_fd);
+ return false;
+ }
+ } else /* !expect_err */ {
+ if (!ASSERT_GT(prog_fd, 0, tag))
+ return false;
+ }
+ return true;
+}
+
+static void verif_log_subtest(const char *name, bool expect_load_error, int log_level)
+{
+ LIBBPF_OPTS(bpf_prog_load_opts, opts);
+ struct {
+ /* strategically placed before others to avoid accidental modification by kernel */
+ char filler[1024];
+ char buf[1024];
+ /* strategically placed after buf[] to catch more accidental corruptions */
+ char reference[1024];
+ } logs;
+ char *exp_log, prog_name[16], op_name[32];
+ struct test_log_buf *skel;
+ struct bpf_program *prog;
+ 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_object__for_each_program(prog, skel->obj) {
+ if (strcmp(bpf_program__name(prog), name) == 0)
+ bpf_program__set_autoload(prog, true);
+ else
+ bpf_program__set_autoload(prog, false);
+ }
+
+ err = test_log_buf__load(skel);
+ if (!expect_load_error && !ASSERT_OK(err, "unexpected_load_failure"))
+ goto cleanup;
+ if (expect_load_error && !ASSERT_ERR(err, "unexpected_load_success"))
+ goto cleanup;
+
+ insns = bpf_program__insns(skel->progs.good_prog);
+ insn_cnt = bpf_program__insn_cnt(skel->progs.good_prog);
+
+ opts.log_buf = logs.reference;
+ opts.log_size = sizeof(logs.reference);
+ opts.log_level = log_level | 8 /* BPF_LOG_FIXED */;
+ prog_fd = bpf_prog_load(BPF_PROG_TYPE_RAW_TRACEPOINT, "log_fixed",
+ "GPL", insns, insn_cnt, &opts);
+ if (!check_prog_load(prog_fd, expect_load_error, "fixed_buf_prog_load"))
+ goto cleanup;
+ close(prog_fd);
+
+ fixed_log_sz = strlen(logs.reference) + 1;
+ if (!ASSERT_GT(fixed_log_sz, 50, "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. This only
+ * works for log_level 2 and log_level 1 + failed program. For log
+ * level 2 we don't reset log at all. For log_level 1 + failed program
+ * we don't get to verification stats output. With log level 1
+ * for successful program final result will be just verifier stats.
+ * But if provided too short log buf, kernel will NULL-out log->ubuf
+ * and will stop emitting further log. This means we'll never see
+ * predictable verifier stats.
+ * Long story short, we do the following -ENOSPC test only for
+ * predictable combinations.
+ */
+ if (log_level >= 2 || expect_load_error) {
+ opts.log_buf = logs.buf;
+ opts.log_level = log_level | 8; /* fixed-length log */
+ opts.log_size = 25;
+
+ 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(logs.buf), 24, "log_fixed_25"))
+ goto cleanup;
+ if (!ASSERT_STRNEQ(logs.buf, logs.reference, 24, op_name))
+ goto cleanup;
+ }
+
+ /* validate rolling verifier log logic: try all variations of log buf
+ * length to force various truncation scenarios
+ */
+ opts.log_buf = logs.buf;
+ opts.log_level = log_level; /* rolling log */
+
+ /* prefill logs.buf with 'A's to detect any write beyond allowed length */
+ memset(logs.filler, 'A', sizeof(logs.filler));
+ logs.filler[sizeof(logs.filler) - 1] = '\0';
+ memset(logs.buf, 'A', sizeof(logs.buf));
+ logs.buf[sizeof(logs.buf) - 1] = '\0';
+
+ 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 (!check_prog_load(prog_fd, expect_load_error, op_name))
+ goto cleanup;
+ close(prog_fd);
+
+ exp_log = logs.reference + fixed_log_sz - i;
+ snprintf(op_name, sizeof(op_name), "log_roll_contents_%d", i);
+ if (!ASSERT_STREQ(logs.buf, exp_log, op_name))
+ goto cleanup;
+
+ printf("CMP:%d\nS1:'%s'\nS2:'%s'\n", strcmp(logs.buf + i, logs.filler + i),
+ logs.buf + i, logs.filler + i);
+
+ /* check that unused portions of logs.buf is not overwritten */
+ snprintf(op_name, sizeof(op_name), "log_roll_unused_tail_%d", i);
+ if (!ASSERT_STREQ(logs.buf + i, logs.filler + i, op_name))
+ goto cleanup;
+ }
+
+cleanup:
+ test_log_buf__destroy(skel);
+}
+
+void test_verifier_log(void)
+{
+ if (test__start_subtest("good_prog-level1"))
+ verif_log_subtest("good_prog", false, 1);
+ if (test__start_subtest("good_prog-level2"))
+ verif_log_subtest("good_prog", false, 2);
+ if (test__start_subtest("bad_prog-level1"))
+ verif_log_subtest("bad_prog", true, 1);
+ if (test__start_subtest("bad_prog-level2"))
+ verif_log_subtest("bad_prog", true, 2);
+}
--
2.34.1
^ permalink raw reply related [flat|nested] 16+ messages in thread