[PATCH bpf-next 0/2] bpf: One basic block and the way to it in the level 1 log

[PATCH bpf-next 0/2] bpf: One basic block and the way to it in the level 1 log

[Alexei Starovoitov]

From: Alexei Starovoitov <ast@kernel.org>

At log level 1 the verifier prints each insn when it verifies it. It used
to follow one path at a time. push_stack() noted the end of the log when
it put a branch aside, and pop_stack() moved the log back there when it
took the branch. So the log was the path from the first insn to the
current one: never larger than the longest path, and for a rejected prog
the path to the error.

Since commit 2d0b457611c0 ("Merge branch
'bpf-a-verifier-that-joins-states'") there are no paths. Basic blocks are
verified in the order of the control flow graph, and the states that get
to a block are joined. pop_stack() is gone, push_stack() notes nothing,
and nothing else moves the log back while a function is verified. The log
holds every block that was verified, each time it was verified.

Two things broke:

- The log of a large prog is many times larger, 15 to 35 times for the
  three below. The text is dropped when the prog is safe, but the buffer
  has to hold the log at its largest. Valid progs of Cilium, katran and
  scx that are loaded the way bpf(2) shows it, with log_level 1 and
  a static buffer, get -ENOSPC with 64K.
- The log of a rejected prog is not the path to the error. It has all
  blocks, both arms of each branch, in the order in which they were
  verified.

1  Two helpers for the log: take its end out, append it later.
2  The level 1 log holds one basic block at a time. When a block is
   rejected the way to it is printed in front of it, from the edges that
   the states at joins came by. Nothing is verified twice. A prog that
   loads pays two stores per state.

log_true_size at level 1           one path   all blocks   this series
  bpf_lxc/tail_ipv4_ct_egress         51434       774446         7652
  bpf_host/cil_to_netdev             101212      1789015         9778
  katran/balancer_ingress            103567      3668559        22603
  progs with -ENOSPC at 64K            2841         5503           45
  the builds of a prog as one           435         1018           23

Level 2 is not changed.

Signed-off-by: Alexei Starovoitov <ast@kernel.org>

Alexei Starovoitov (2):
  bpf: Take the end of the verifier log out and append it later
  bpf: Keep one basic block in the level 1 log and print the way to it

 include/linux/bpf_verifier.h                       |  10 ++
 kernel/bpf/flow.c                                  | 111 ++++++++++++++++++--
 kernel/bpf/log.c                                   |  47 +++++++++
 kernel/bpf/verifier.c                              |  20 +++-
 .../testing/selftests/bpf/progs/linked_list_peek.c |   2 +-
 tools/testing/selftests/bpf/progs/rbtree_search.c  |   4 +-
 .../testing/selftests/bpf/progs/verifier_bounds.c  |   2 +-
 7 files changed, 181 insertions(+), 15 deletions(-)

-- 
2.55.0

[PATCH bpf-next 1/2] bpf: Take the end of the verifier log out and append it later

[Alexei Starovoitov]

From: Alexei Starovoitov <ast@kernel.org>

When a prog is rejected the log ends with the basic block that fails and
the message. How the verifier got to that block can be told only then,
and a reader wants it in front of the block:

  the way to the block            printed last
  the block, the message          printed first

The block is not going to be verified again to print it again. The kernel
has no copy of the text either: the log is in the buffer of the user.

bpf_vlog_stash() reads back what was written since a position and moves
the log back to it. bpf_vlog_unstash() appends that text to what was
written in between.

A buffer that is too small holds a part of the text: a rolling one has
lost the start, a fixed one the end. There may be no buffer at all. What
is not there is counted. So log_true_size, -ENOSPC and the bytes in the
buffer are those of a log that was written in the final order, whatever
the size of the buffer.

The stash is never larger than the buffer, which may have 1G. When memory
is short the allocation has to fail and not to call the OOM killer:
__GFP_RETRY_MAYFAIL. The log is left as it is then.

The text is not looked at. If another thread has changed it the caller
gets these bytes back, cut at a zero byte.

Signed-off-by: Alexei Starovoitov <ast@kernel.org>
---
 include/linux/bpf_verifier.h |  9 +++++++
 kernel/bpf/log.c             | 47 ++++++++++++++++++++++++++++++++++++
 2 files changed, 56 insertions(+)

diff --git a/include/linux/bpf_verifier.h b/include/linux/bpf_verifier.h
index 656ed55b96ec..15619edc8f03 100644
--- a/include/linux/bpf_verifier.h
+++ b/include/linux/bpf_verifier.h
@@ -1417,6 +1417,15 @@ __printf(2, 3) void bpf_log(struct bpf_verifier_log *log,
 int bpf_vlog_init(struct bpf_verifier_log *log, u32 log_level,
 		  char __user *log_buf, u32 log_size);
 void bpf_vlog_reset(struct bpf_verifier_log *log, u64 new_pos);
+
+/* The end of the log, taken out of it by bpf_vlog_stash() */
+struct bpf_vlog_stash {
+	char *buf;
+	u64 len, lost_start, lost_end;
+};
+
+int bpf_vlog_stash(struct bpf_verifier_log *log, u64 pos, struct bpf_vlog_stash *stash);
+void bpf_vlog_unstash(struct bpf_verifier_log *log, struct bpf_vlog_stash *stash);
 int bpf_vlog_finalize(struct bpf_verifier_log *log, u32 *log_size_actual);
 
 __printf(3, 4) void verbose_linfo(struct bpf_verifier_env *env,
diff --git a/kernel/bpf/log.c b/kernel/bpf/log.c
index 1253118dfd05..84659a757b43 100644
--- a/kernel/bpf/log.c
+++ b/kernel/bpf/log.c
@@ -177,6 +177,53 @@ void bpf_vlog_reset(struct bpf_verifier_log *log, u64 new_pos)
 		log->ubuf = NULL;
 }
 
+/*
+ * Take what was written since @pos out of the log. bpf_vlog_unstash() appends it to what is
+ * written in between. The text is in the buffer of the user and nowhere else. What the buffer
+ * doesn't hold, the start of the text if it's rolling and the end if it's fixed, is counted.
+ */
+int bpf_vlog_stash(struct bpf_verifier_log *log, u64 pos, struct bpf_vlog_stash *stash)
+{
+	u64 from = max(pos, log->start_pos), to = log->end_pos, i;
+	u32 off, n;
+
+	if (!log->ubuf)
+		from = to;
+	else if (log->level & BPF_LOG_FIXED)
+		to = clamp(log->len_total - 1ULL, from, to);
+	stash->lost_start = from - pos;
+	stash->lost_end = log->end_pos - to;
+	stash->len = to - from;
+	/* as large as the buffer at worst: fail before the OOM killer is called */
+	stash->buf = kvzalloc(stash->len, GFP_KERNEL_ACCOUNT | __GFP_NOWARN | __GFP_RETRY_MAYFAIL);
+	if (!stash->buf)
+		return -ENOMEM;
+	/* two pieces if it wraps around */
+	for (i = from; i < to && log->ubuf; i += n) {
+		div_u64_rem(i, log->len_total, &off);
+		n = min(to - i, log->len_total - off);
+		if (copy_from_user(stash->buf + (i - from), log->ubuf + off, n))
+			log->ubuf = NULL;
+	}
+	bpf_vlog_reset(log, pos);
+	return 0;
+}
+
+void bpf_vlog_unstash(struct bpf_verifier_log *log, struct bpf_vlog_stash *stash)
+{
+	u64 i, n;
+
+	log->end_pos += stash->lost_start;
+	for (i = 0; i < stash->len; i += n) {
+		n = min(stash->len - i, sizeof(log->kbuf) - 1);
+		bpf_log(log, "%.*s", (int)n, stash->buf + i);
+		cond_resched();
+	}
+	log->end_pos += stash->lost_end;
+	bpf_vlog_update_len_max(log, 1);
+	kvfree(stash->buf);
+}
+
 static void bpf_vlog_reverse_kbuf(char *buf, int len)
 {
 	int i, j;
-- 
2.55.0

[PATCH bpf-next 2/2] bpf: Keep one basic block in the level 1 log and print the way to it

[Alexei Starovoitov]

From: Alexei Starovoitov <ast@kernel.org>

bpf(2) shows how to load a prog: .log_level = 1 and a static buffer.
Cilium's bpf_lxc/tail_ipv4_ct_egress loaded that way with 64K. Now it gets
-ENOSPC, like 2097 progs of the selftests, Cilium, scx, katran, bpfjailer
and Rust crates.

At level 1 each insn is printed when it is verified. The verifier used to
follow one path at a time. At a conditional jump push_stack() put the
other branch aside and noted the end of the log. When the path was done
pop_stack() took the branch and moved the log back:

  push_stack():  elem->log_pos = env->log.end_pos;
  pop_stack():   bpf_vlog_reset(&env->log, head->log_pos);

So the log was the path from the first insn to the current one. It never
got larger than the longest path, and when a prog was rejected it was the
path to the error.

Now there are no paths. Basic blocks are verified in the order of the
control flow graph, and the states that get to a block are joined. What
push_stack() puts aside goes to the block that it is for. pop_stack() and
log_pos are gone, and nothing else moves the log back while a function is
verified. Each block adds its text each time it is verified: 4057 insns
and 774446 bytes for tail_ipv4_ct_egress, whose longest path had 51434.

The text is dropped when the prog turns out to be safe. That doesn't help:
bpf_vlog_finalize() compares the buffer with len_max, the largest size
that the log ever had. And the log of a rejected prog is not the path to
the error any more. It has all blocks, both arms of each branch, in the
order in which they were verified.

The old log cannot come back as it was. The state at the start of a block
is the join of all that got there: no path leads to it.

Move the log back in front of each basic block, so that it holds one block
at a time. When a block is rejected print the way to it from what the
verifier holds at that time. It keeps the states where ways meet. Such a
state knows the edge that it came by, after a join the edge that changed
it last: the edge that brought the bad value. There may be several states
at an insn, so a state gets a u32 that tells which kept state it comes
from. A block in between has one predecessor. The block that fails is in
the log already: stash it, print the way, append it. Nothing is verified
twice.

  if (skb->mark == 1)      i = skb->len & 63;
  else if (skb->mark == 2) i = skb->priority;
  else                     i = 7;
  if (skb->protocol == 8)  v[0] = 1;
  return v[i];

  from -1 to 0: R1=ctx() R10=fp0
  ...
  10: (16) if w2 == 0x2 goto pc+5
  ; i = skb->priority; @ pick.bpf.c:22
  16: (61) r1 = *(u32 *)(r6 +32)
  from 16 to 17: R0=map_value(map=m,ks=4,vs=64) R1=scalar(smin=0,smax=..
  ; if (skb->protocol == 8) @ pick.bpf.c:25
  17: (61) r2 = *(u32 *)(r6 +16)
  18: (56) if w2 != 0x8 goto pc+2
  21: R0=map_value(map=m,ks=4,vs=64) R1=scalar(smin=0,smax=umax=0xfff..
  ; return v[i]; @ pick.bpf.c:27
  21: (0f) r0 += r1               ; R0=map_value(map=m,ks=4,vs=64,smin=..
  22: (71) r7 = *(u8 *)(r0 +0)
  R0 unbounded memory access, make sure to bounds check any such access

A block is on the way once, so the way goes around a loop once. Where
a block would come again the way goes on from its dominator: all that gets
into the loop goes through it. The earlier rounds are left out, what is in
front of the loop is not. A function that is verified in the frames of its
caller is on the way once too, for its last call. Its dominators end at
its first insn, so the way begins where the call before that one returns.

A signal ends the print. A round that do_check_all() drops gets no way, so
bpf_flow_loops_lost_bound() can be asked twice now. Level 1 doesn't show
the states behind the insns of the way and the bodies of subprogs that are
verified on their own. Level 2 has them. It is not changed, and six tests
that look at such a state get __log_level(2), with the five others that
come out of the same macros.

log_true_size at level 1           one path   all blocks   this patch
  bpf_lxc/tail_ipv4_ct_egress         51434       774446         7652
  bpf_host/cil_to_netdev             101212      1789015         9778
  katran/balancer_ingress            103567      3668559        22603
  progs with -ENOSPC at 64K            2841         5503           45
  the builds of a prog as one           435         1018           23

A prog that loads pays two stores of a u32 per state: ftrace sees no call
of bpf_flow_print_way(). The longest way, 713 lines, takes 0.4 ms.

Fixes: 5395aa9bbeb5 ("bpf: Verify programs as a fixpoint over the control flow graph")
Signed-off-by: Alexei Starovoitov <ast@kernel.org>
---
 include/linux/bpf_verifier.h                  |   1 +
 kernel/bpf/flow.c                             | 111 ++++++++++++++++--
 kernel/bpf/verifier.c                         |  20 +++-
 .../selftests/bpf/progs/linked_list_peek.c    |   2 +-
 .../selftests/bpf/progs/rbtree_search.c       |   4 +-
 .../selftests/bpf/progs/verifier_bounds.c     |   2 +-
 6 files changed, 125 insertions(+), 15 deletions(-)

diff --git a/include/linux/bpf_verifier.h b/include/linux/bpf_verifier.h
index 15619edc8f03..4771c55d8f41 100644
--- a/include/linux/bpf_verifier.h
+++ b/include/linux/bpf_verifier.h
@@ -1553,6 +1553,7 @@ int bpf_flow_deliver(struct bpf_verifier_env *env, struct bpf_verifier_state *st
 int bpf_flow_guard_edge(struct bpf_verifier_env *env, struct bpf_verifier_state *st,
 			int insn_idx, int prev_insn_idx, enum bpf_guard_edge edge);
 int bpf_flow_next(struct bpf_verifier_env *env, int *prev_insn_idx);
+void bpf_flow_print_way(struct bpf_verifier_env *env, u64 log_pos, int head, int i);
 int bpf_flow_call(struct bpf_verifier_env *env, struct bpf_verifier_state *caller,
 		  struct bpf_verifier_state *entry, int subprog, int call_idx);
 int bpf_flow_exit(struct bpf_verifier_env *env, struct bpf_verifier_state *st, int exit_idx);
diff --git a/kernel/bpf/flow.c b/kernel/bpf/flow.c
index e6d1817ffa57..c9458b3ad114 100644
--- a/kernel/bpf/flow.c
+++ b/kernel/bpf/flow.c
@@ -92,6 +92,7 @@ struct flow_state {
 	struct rb_node rb;		/* pending states */
 	int prev_insn_idx;
 	u32 seq;
+	u32 from;			/* seq of the last state on the way to it that is kept */
 	struct flow_shape shape;
 	u16 joins;
 	bool pending;
@@ -178,6 +179,7 @@ struct bpf_flow {
 	struct list_head kept;
 	struct bpf_verifier_state tmp;
 	u32 seq;
+	u32 from;			/* flow_state.from of what comes from the current state */
 	u32 live_states;
 };
 
@@ -416,17 +418,14 @@ void bpf_flow_next_is_no_bound(struct bpf_verifier_env *env, int insn_idx, int h
 bool bpf_flow_loops_lost_bound(struct bpf_verifier_env *env)
 {
 	struct bpf_loop *loop;
-	bool lost = false;
 	int h;
 
 	for (h = 0; h < env->prog->len; h++) {
 		loop = env->insn_aux_data[h].loop;
-		if (!loop || !loop->rt_bounded || flow_loop_is_bounded(env, h))
-			continue;
-		loop->rt_bounded = false;
-		lost = true;
+		if (loop && loop->rt_bounded && !flow_loop_is_bounded(env, h))
+			return true;
 	}
-	return lost;
+	return false;
 }
 
 /*
@@ -459,8 +458,12 @@ void bpf_flow_new_round(struct bpf_verifier_env *env)
 	env->guards_late = false;
 	for (i = 0; i < env->prog->len; i++) {
 		aux[i].guard_edge_dropped = false;
-		if (aux[i].loop)
-			aux[i].loop->no_guard_edges = false;
+		if (!aux[i].loop)
+			continue;
+		aux[i].loop->no_guard_edges = false;
+		/* what the last round found out */
+		if (aux[i].loop->rt_bounded)
+			aux[i].loop->rt_bounded = flow_loop_is_bounded(env, i);
 	}
 }
 
@@ -2883,6 +2886,7 @@ static struct flow_state *flow_new_state(struct bpf_verifier_env *env, int prev_
 		return NULL;
 	s->prev_insn_idx = prev_insn_idx;
 	s->seq = ++flow->seq;
+	s->from = flow->from;
 	env->total_states++;
 	flow->live_states++;
 	env->peak_states = max(env->peak_states, flow->live_states);
@@ -3308,8 +3312,11 @@ int bpf_flow_next(struct bpf_verifier_env *env, int *prev_insn_idx)
 
 	env->insn_idx = s->st.insn_idx;
 	*prev_insn_idx = s->prev_insn_idx;
-	if (test_bit(s->st.insn_idx, flow->keep))
+	if (test_bit(s->st.insn_idx, flow->keep)) {
+		flow->from = s->seq;
 		return bpf_copy_verifier_state(env->cur_state, &s->st);
+	}
+	flow->from = s->from;
 	*env->cur_state = s->st;
 	memset(&s->st, 0, sizeof(s->st));
 	s->st.insn_idx = env->insn_idx;
@@ -3317,3 +3324,89 @@ int bpf_flow_next(struct bpf_verifier_env *env, int *prev_insn_idx)
 	flow_free_state(env, s);
 	return 0;
 }
+
+/* A basic block on the way to the block that is rejected, up to the insn that leads on */
+struct flow_step {
+	const struct flow_state *s;	/* the state at its head, if one is kept */
+	int head, last;
+};
+
+/*
+ * The state at @head with that @seq. If it is gone a state that came later took its place:
+ * the last one then.
+ */
+static const struct flow_state *flow_find_state(const struct bpf_flow *flow, int head, u32 seq)
+{
+	const struct list_head *list = &flow->states[head].list;
+	const struct flow_state *s;
+
+	if (!test_bit(head, flow->keep))
+		return NULL;
+	list_for_each_entry(s, list, node)
+		if (s->seq == seq)
+			return s;
+	return list_empty(list) ? NULL : list_last_entry(list, struct flow_state, node);
+}
+
+/*
+ * The basic block at @head, which the current state got to from insn @i, is rejected. The block
+ * and the message are what was printed since @log_pos. Print the way to the block in front of it.
+ *
+ * The way is put together backwards from what is there. A state that is kept knows the edge that
+ * it came by, after a join the edge that changed it last, and the kept state that it comes from.
+ * A block whose state is not kept has one predecessor, which is its dominator.
+ * A block is on the way once. Where it would come again, after a round of a loop, the way goes on
+ * from its dominator: all that gets into the loop goes through it.
+ */
+void bpf_flow_print_way(struct bpf_verifier_env *env, u64 log_pos, int head, int i)
+{
+	struct bpf_insn *insns = env->prog->insnsi;
+	const struct bpf_flow *flow = env->flow;
+	const struct flow_state *s;
+	struct bpf_vlog_stash stash;
+	struct flow_step *way, *w;
+	u32 from = flow->from, cnt = 0;
+	unsigned long *seen;
+
+	seen = bitmap_zalloc(flow->len, GFP_KERNEL_ACCOUNT);
+	way = kvmalloc_array(bitmap_weight(flow->point, flow->len), sizeof(*way),
+			     GFP_KERNEL_ACCOUNT);
+	if (!seen || !way)
+		goto out;
+
+	s = flow_find_state(flow, head, from);
+	from = s ? s->from : from;
+	while (i >= 0) {
+		head = find_last_bit(flow->point, i + 1);
+		s = NULL;
+		if (!__test_and_set_bit(head, seen)) {
+			s = flow_find_state(flow, head, from);
+			way[cnt++] = (struct flow_step){ s, head, i };
+		}
+		from = s ? s->from : from;
+		i = s ? s->prev_insn_idx : env->idoms[head];
+		cond_resched();
+	}
+
+	if (!cnt || bpf_vlog_stash(&env->log, log_pos, &stash))
+		goto out;
+	env->prev_linfo = NULL;
+	while (cnt-- && !signal_pending(current)) {
+		w = &way[cnt];
+		if (w->s) {
+			verbose(env, "from %d to %d:", w->s->prev_insn_idx, w->head);
+			print_verifier_state(env, &w->s->st, w->s->st.curframe, true);
+		}
+		for (i = w->head; i <= w->last; i += 1 + bpf_is_ldimm64(&insns[i])) {
+			verbose_linfo(env, i, "; ");
+			verbose(env, "%d: ", i);
+			bpf_verbose_insn(env, &insns[i]);
+			verbose(env, "\n");
+		}
+		cond_resched();
+	}
+	bpf_vlog_unstash(&env->log, &stash);
+out:
+	bitmap_free(seen);
+	kvfree(way);
+}
diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
index fd333b1063c3..20b1b9ff574c 100644
--- a/kernel/bpf/verifier.c
+++ b/kernel/bpf/verifier.c
@@ -22035,9 +22035,17 @@ static int do_check_block(struct bpf_verifier_env *env, int prev_insn_idx)
 	}
 }
 
+/* All is done again, whatever came out, see do_check_all() */
+static bool round_is_dropped(struct bpf_verifier_env *env)
+{
+	return (env->restart && bpf_flow_loops_lost_bound(env)) || env->guards_late;
+}
+
 static int do_check(struct bpf_verifier_env *env)
 {
-	int prev_insn_idx = -1;
+	bool level1 = (env->log.level & BPF_LOG_LEVEL) == BPF_LOG_LEVEL1;
+	u64 log_pos = env->log.end_pos;
+	int prev_insn_idx = -1, insn_idx;
 	int err;
 
 	err = bpf_flow_deliver(env, env->cur_state, env->insn_idx, -1);
@@ -22049,7 +22057,15 @@ static int do_check(struct bpf_verifier_env *env)
 			break;
 		/* What is known about how the state came to be is not kept with it. */
 		bpf_diag_event_log_restore(env, 0);
+		/* Neither is the text: the level 1 log has one basic block at a time. */
+		if (level1) {
+			bpf_vlog_reset(&env->log, log_pos);
+			env->prev_linfo = NULL;
+		}
+		insn_idx = env->insn_idx;
 		err = do_check_block(env, prev_insn_idx);
+		if (err && level1 && !round_is_dropped(env))
+			bpf_flow_print_way(env, log_pos, insn_idx, prev_insn_idx);
 	}
 	return err;
 }
@@ -23435,7 +23451,7 @@ static int do_check_all(struct bpf_verifier_env *env)
 		bpf_flow_new_round(env);
 		ret = do_check_main(env);
 		ret = ret ?: do_check_subprogs(env);
-		if (!(env->restart && bpf_flow_loops_lost_bound(env)) && !env->guards_late)
+		if (!round_is_dropped(env))
 			return ret;
 		/* the log is dropped when a function is found to be safe */
 		bpf_vlog_reset(&env->log, min(log_pos, env->log.end_pos));
diff --git a/tools/testing/selftests/bpf/progs/linked_list_peek.c b/tools/testing/selftests/bpf/progs/linked_list_peek.c
index 264e81bfb287..d881c0210816 100644
--- a/tools/testing/selftests/bpf/progs/linked_list_peek.c
+++ b/tools/testing/selftests/bpf/progs/linked_list_peek.c
@@ -83,7 +83,7 @@ long list_peek(void *ctx)
 
 #define TEST_FB(op, dolock)					\
 SEC("syscall")							\
-__failure __msg(MSG)						\
+__failure __msg(MSG) __log_level(2)				\
 long test_##op##_spinlock_##dolock(void *ctx)			\
 {								\
 	struct bpf_list_node *l_n;				\
diff --git a/tools/testing/selftests/bpf/progs/rbtree_search.c b/tools/testing/selftests/bpf/progs/rbtree_search.c
index b05565d1db0d..da2112c89d96 100644
--- a/tools/testing/selftests/bpf/progs/rbtree_search.c
+++ b/tools/testing/selftests/bpf/progs/rbtree_search.c
@@ -133,7 +133,7 @@ long rbtree_search(void *ctx)
 
 #define TEST_ROOT(dolock)				\
 SEC("syscall")						\
-__failure __msg(MSG)					\
+__failure __msg(MSG) __log_level(2)			\
 long test_root_spinlock_##dolock(void *ctx)		\
 {							\
 	struct bpf_rb_node *rb_n;			\
@@ -152,7 +152,7 @@ long test_root_spinlock_##dolock(void *ctx)		\
 
 #define TEST_LR(op, dolock)				\
 SEC("syscall")						\
-__failure __msg(MSG)					\
+__failure __msg(MSG) __log_level(2)			\
 long test_##op##_spinlock_##dolock(void *ctx)		\
 {							\
 	struct bpf_rb_node *rb_n;			\
diff --git a/tools/testing/selftests/bpf/progs/verifier_bounds.c b/tools/testing/selftests/bpf/progs/verifier_bounds.c
index 28d48e5fbc4f..f55d58af8004 100644
--- a/tools/testing/selftests/bpf/progs/verifier_bounds.c
+++ b/tools/testing/selftests/bpf/progs/verifier_bounds.c
@@ -1648,7 +1648,7 @@ l0_%=:	r0 = 0;				\
  */
 SEC("socket")
 __description("bounds deduction cross sign boundary, two overlaps")
-__failure
+__failure __log_level(2)
 __msg("3: (2d) if r0 > r1 {{.*}} R0=scalar(smin=smin32=-128,smax=smax32=127)")
 /* smin=-128 includes point 0xffffffffffffff80 */
 __msg("frame pointer is read only")
-- 
2.55.0

Re: [PATCH bpf-next 2/2] bpf: Keep one basic block in the level 1 log and print the way to it

[sashiko-bot]

Thank you for your contribution! Sashiko AI review found 2 potential
issues to consider:
- [Medium] bpf: preserve flow->from across subprogram calls in
  bpf_flow_call()
- [Low] bpf: clear env->prev_log_pos when resetting level 1 log in
  do_check()
--

commit 436e80edd288c8e9b5661dd9e9cfd3aca7f99381
Author: Alexei Starovoitov <ast@kernel.org>

bpf: Keep one basic block in the level 1 log and print the way to it

This commit rewinds the level 1 verifier log before each basic block and
reconstructs and prints the path of basic blocks leading to a rejected block
on verification failure.

> diff --git a/kernel/bpf/flow.c b/kernel/bpf/flow.c
> index e6d1817ffa57d..c9458b3ad114a 100644
> --- a/kernel/bpf/flow.c
> +++ b/kernel/bpf/flow.c
[ ... ]
> @@ -2883,6 +2886,7 @@ static struct flow_state *flow_new_state(struct bpf_verifier_env *env, int prev_
>  		return NULL;
>  	s->prev_insn_idx = prev_insn_idx;
>  	s->seq = ++flow->seq;
> +	s->from = flow->from;
>  	env->total_states++;
>  	flow->live_states++;
>  	env->peak_states = max(env->peak_states, flow->live_states);
> @@ -3308,8 +3312,11 @@ int bpf_flow_next(struct bpf_verifier_env *env, int *prev_insn_idx)
>  
>  	env->insn_idx = s->st.insn_idx;
>  	*prev_insn_idx = s->prev_insn_idx;
> -	if (test_bit(s->st.insn_idx, flow->keep))
> +	if (test_bit(s->st.insn_idx, flow->keep)) {
> +		flow->from = s->seq;
>  		return bpf_copy_verifier_state(env->cur_state, &s->st);
> +	}
> +	flow->from = s->from;
>  	*env->cur_state = s->st;
>  	memset(&s->st, 0, sizeof(s->st));
>  	s->st.insn_idx = env->insn_idx;
> @@ -3317,3 +3324,89 @@ int bpf_flow_next(struct bpf_verifier_env *env, int *prev_insn_idx)
>  	flow_free_state(env, s);
>  	return 0;
>  }
> +
> +/* A basic block on the way to the block that is rejected, up to the insn that leads on */
> +struct flow_step {
> +	const struct flow_state *s;	/* the state at its head, if one is kept */
> +	int head, last;
> +};
> +
> +/*
> + * The state at @head with that @seq. If it is gone a state that came later took its place:
> + * the last one then.
> + */
> +static const struct flow_state *flow_find_state(const struct bpf_flow *flow, int head, u32 seq)
> +{
> +	const struct list_head *list = &flow->states[head].list;
> +	const struct flow_state *s;
> +
> +	if (!test_bit(head, flow->keep))
> +		return NULL;
> +	list_for_each_entry(s, list, node)
> +		if (s->seq == seq)
> +			return s;
> +	return list_empty(list) ? NULL : list_last_entry(list, struct flow_state, node);
> +}

[Severity: Medium]
Does flow_find_state() look up the caller's basic block with a callee sequence
number after a call to a static subprogram that is verified on its own?

When bpf_flow_call() parks the waiting caller state w, it does not save
w->from = flow->from.  Verifying the callee then overwrites flow->from with
the callee's kept state sequence numbers, and flow_apply_exit() creates the
resumed caller state at call_idx + 1 (or call_idx) via flow_new_state() using
that overwritten flow->from:

kernel/bpf/flow.c:flow_apply_exit() {
	...
	if (!err)
		err = bpf_flow_deliver(env, &st, call_idx + 1, call_idx);
	bpf_free_verifier_state(&st, false);
	if (err != 1)
		return err;
	...
	s = flow_new_state(env, w->st.last_insn_idx);
	...
}

If verification later fails in the caller, bpf_flow_print_way() steps back to
call_idx carrying the callee's seq in from.  When multiple states were kept at
the caller's basic block, s->seq == seq never matches in flow_find_state(),
so it falls back to list_last_entry() and prints the wrong state and incoming
edge for the caller.  Saving flow->from in w->from in bpf_flow_call() and
restoring flow->from = w->from in flow_apply_exit() would preserve the
caller's sequence number across the call.

> diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
> index fd333b1063c3d..20b1b9ff574c7 100644
> --- a/kernel/bpf/verifier.c
> +++ b/kernel/bpf/verifier.c
> @@ -22049,7 +22057,15 @@ static int do_check(struct bpf_verifier_env *env)
>  			break;
>  		/* What is known about how the state came to be is not kept with it. */
>  		bpf_diag_event_log_restore(env, 0);
> +		/* Neither is the text: the level 1 log has one basic block at a time. */
> +		if (level1) {
> +			bpf_vlog_reset(&env->log, log_pos);
> +			env->prev_linfo = NULL;
> +		}

[Severity: Low]
Should this also reset env->prev_log_pos = 0 when rewinding env->log?

When a previous function verification pass leaves a small env->prev_log_pos
that happens to match log_pos after do_check_common() prints the "Validating
<func>() func#<n>..." header line for a global subprogram, print_insn_state()
on the first instruction of the basic block sees
env->prev_log_pos == env->log.end_pos:

kernel/bpf/log.c:print_insn_state() {
	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_pos - 1);
		verbose(env, "%*c;", bpf_vlog_alignment(env->prev_insn_print_pos), ' ');
	} else {
		verbose(env, "%d:", env->insn_idx);
	}
	...
}

That strips the trailing newline from the "Validating ..." header line and
appends the initial state inline with a semicolon instead of printing
"<insn_idx>:".

-- 
Sashiko AI review · https://sashiko.dev/#/patchset/20261108053937.4134138-1-alexei.starovoitov@gmail.com?part=2

Re: [PATCH bpf-next 1/2] bpf: Take the end of the verifier log out and append it later

[sashiko-bot]

Thank you for your contribution! Sashiko AI review found 1 potential
issue to consider:
- [Medium] bpf: rolling log window corruption and bad NUL cut in
  bpf_vlog_unstash()
--

commit 77a6b70f8e6a46314ce083390eb008b9b5d0b118
Author: Alexei Starovoitov <ast@kernel.org>

bpf: Take the end of the verifier log out and append it later

This commit adds bpf_vlog_stash() and bpf_vlog_unstash() to copy the tail
of the verifier log out of the user buffer, reset the log position, and
append the stashed text later.

> diff --git a/kernel/bpf/log.c b/kernel/bpf/log.c
> index 1253118dfd051..84659a757b43c 100644
> --- a/kernel/bpf/log.c
> +++ b/kernel/bpf/log.c
> @@ -177,6 +177,53 @@ void bpf_vlog_reset(struct bpf_verifier_log *log, u64 new_pos)
>  		log->ubuf = NULL;
>  }
>  
> +/*
> + * Take what was written since @pos out of the log. bpf_vlog_unstash() appends it to what is
> + * written in between. The text is in the buffer of the user and nowhere else. What the buffer
> + * doesn't hold, the start of the text if it's rolling and the end if it's fixed, is counted.
> + */
> +int bpf_vlog_stash(struct bpf_verifier_log *log, u64 pos, struct bpf_vlog_stash *stash)
> +{
> +	u64 from = max(pos, log->start_pos), to = log->end_pos, i;
> +	u32 off, n;
> +
> +	if (!log->ubuf)
> +		from = to;
> +	else if (log->level & BPF_LOG_FIXED)
> +		to = clamp(log->len_total - 1ULL, from, to);
> +	stash->lost_start = from - pos;
> +	stash->lost_end = log->end_pos - to;
> +	stash->len = to - from;
> +	/* as large as the buffer at worst: fail before the OOM killer is called */
> +	stash->buf = kvzalloc(stash->len, GFP_KERNEL_ACCOUNT | __GFP_NOWARN | __GFP_RETRY_MAYFAIL);
> +	if (!stash->buf)
> +		return -ENOMEM;
> +	/* two pieces if it wraps around */
> +	for (i = from; i < to && log->ubuf; i += n) {
> +		div_u64_rem(i, log->len_total, &off);
> +		n = min(to - i, log->len_total - off);
> +		if (copy_from_user(stash->buf + (i - from), log->ubuf + off, n))
> +			log->ubuf = NULL;
> +	}
> +	bpf_vlog_reset(log, pos);
> +	return 0;
> +}
> +
> +void bpf_vlog_unstash(struct bpf_verifier_log *log, struct bpf_vlog_stash *stash)
> +{
> +	u64 i, n;
> +
> +	log->end_pos += stash->lost_start;
> +	for (i = 0; i < stash->len; i += n) {
> +		n = min(stash->len - i, sizeof(log->kbuf) - 1);
> +		bpf_log(log, "%.*s", (int)n, stash->buf + i);
> +		cond_resched();
> +	}

[Severity: Medium]
Can advancing log->end_pos by stash->lost_start without updating
log->start_pos leave an unwritten gap inside the rolling log window?

When a rolling log has wrapped past pos (log->start_pos > pos),
bpf_vlog_stash() records stash->lost_start = log->start_pos - pos and calls
bpf_vlog_reset(log, pos), which resets both log->start_pos and log->end_pos
to pos.  After intermediate text is logged up to E1, bpf_vlog_unstash()
adds stash->lost_start to log->end_pos (advancing it to E2) without
writing to log->ubuf in [E1, E2) or advancing log->start_pos.

This relies on the replay loop emitting log->len_total - 1 bytes so
bpf_verifier_vlog() pushes log->start_pos up to E2.  If the loop emits
fewer bytes (for example, because another thread wrote a zero byte into the
user buffer, or bpf_vlog_reset() earlier shrank log->end_pos -
log->start_pos below log->len_total - 1), log->start_pos stays below E2 and
bpf_vlog_finalize() rotates the NUL terminator at E1 and stale bytes in
[E1, E2) into the middle of the caller's log buffer.

In addition, because the replay loop formats stash->buf in chunks of
sizeof(log->kbuf) - 1 bytes via "%.*s", a zero byte in one chunk only
truncates that chunk in vscnprintf() instead of cutting the rest of
stash->buf, while still advancing log->end_pos by fewer than stash->len
bytes.

-- 
Sashiko AI review · https://sashiko.dev/#/patchset/20261108053937.4134138-1-alexei.starovoitov@gmail.com?part=1

Re: [PATCH bpf-next 1/2] bpf: Take the end of the verifier log out and append it later

[Alexei Starovoitov]

On Sat, Nov 07, 2026 at 10:03 PM sashiko-bot@kernel.org <sashiko-bot@kernel.org> wrote:
>> +	log->end_pos += stash->lost_start;
>> +	for (i = 0; i < stash->len; i += n) {
>> +		n = min(stash->len - i, sizeof(log->kbuf) - 1);
>> +		bpf_log(log, "%.*s", (int)n, stash->buf + i);
>
> [Severity: Medium]
> Can advancing log->end_pos by stash->lost_start without updating
> log->start_pos leave an unwritten gap inside the rolling log window?
[...]
> This relies on the replay loop emitting log->len_total - 1 bytes so
> bpf_verifier_vlog() pushes log->start_pos up to E2.  If the loop emits
> fewer bytes (for example, because another thread wrote a zero byte into the
> user buffer, or bpf_vlog_reset() earlier shrank log->end_pos -
> log->start_pos below log->len_total - 1), log->start_pos stays below E2 and

No. Not a bug.
do_check() moves the log back to log_pos in front of each block, so
start_pos <= log_pos there.
lost_start != 0 means that the block rolled over log_pos. The buffer is
full then: stash->len == len_total - 1.
At level 1 the only bpf_vlog_reset() inside a block is the one in
print_insn_state(). It takes one '\n' out, and verbose() in the next line
fills the buffer again.
So the replay moves start_pos to E2.

A thread that writes zeros into the buffer damages its own log.
It's already explained in the commit log.

> In addition, because the replay loop formats stash->buf in chunks of
> sizeof(log->kbuf) - 1 bytes via "%.*s", a zero byte in one chunk only
> truncates that chunk in vscnprintf() instead of cutting the rest of

Not an issue. Only another thread of the caller puts a zero byte there.
Less text comes back then.

Re: [PATCH bpf-next 2/2] bpf: Keep one basic block in the level 1 log and print the way to it

[Alexei Starovoitov]

On Sat, Nov 07, 2026 at 10:02 PM sashiko-bot@kernel.org <sashiko-bot@kernel.org> wrote:
>> @@ -2883,6 +2886,7 @@ static struct flow_state *flow_new_state(struct bpf_verifier_env *env, int prev_
>>  	s->seq = ++flow->seq;
>> +	s->from = flow->from;
>
> [Severity: Medium]
> Does flow_find_state() look up the caller's basic block with a callee sequence
> number after a call to a static subprogram that is verified on its own?
[...]
> If verification later fails in the caller, bpf_flow_print_way() steps back to
> call_idx carrying the callee's seq in from.  When multiple states were kept at
> the caller's basic block, s->seq == seq never matches in flow_find_state(),
> so it falls back to list_last_entry() and prints the wrong state and incoming
> edge for the caller.

Not a bug. It's a limitation.
When the seq is not at that insn flow_find_state() takes the last state
there. With one state at the insn that's the right one.
With several states the way can show the edge of another state.
The way is a help for the reader. Nothing depends on it.
Level 2 has all states.

>> +		if (level1) {
>> +			bpf_vlog_reset(&env->log, log_pos);
>> +			env->prev_linfo = NULL;
>> +		}
>
> [Severity: Low]
> Should this also reset env->prev_log_pos = 0 when rewinding env->log?

No. Not from this patch.
Inside a function every prev_log_pos is larger than log_pos.
The rewind cannot make them equal.
The case that you describe is the first block of a global function.
The log is at log_pos already and this bpf_vlog_reset() does nothing.
prev_log_pos is stale there without the patch too: do_check_common()
does bpf_vlog_reset(&env->log, 0) after the previous function.
The two have to match to the byte, and a newline is all that is lost.

Re: [PATCH bpf-next 0/2] bpf: One basic block and the way to it in the level 1 log

[patchwork-bot+netdevbpf]

Hello:

This series was applied to bpf/bpf-next.git (master)
by Alexei Starovoitov <ast@kernel.org>:

On Sun,  8 Nov 2026 05:39:35 +0000 you wrote:
> From: Alexei Starovoitov <ast@kernel.org>
> 
> At log level 1 the verifier prints each insn when it verifies it. It used
> to follow one path at a time. push_stack() noted the end of the log when
> it put a branch aside, and pop_stack() moved the log back there when it
> took the branch. So the log was the path from the first insn to the
> current one: never larger than the longest path, and for a rejected prog
> the path to the error.
> 
> [...]

Here is the summary with links:
  - [bpf-next,1/2] bpf: Take the end of the verifier log out and append it later
    https://git.kernel.org/bpf/bpf-next/c/ffb7ea52c7af
  - [bpf-next,2/2] bpf: Keep one basic block in the level 1 log and print the way to it
    https://git.kernel.org/bpf/bpf-next/c/35fca41d5746

You are awesome, thank you!
-- 
Deet-doot-dot, I am a bot.
https://korg.docs.kernel.org/patchwork/pwbot.html