* [PATCH v2 bpf-next 0/3] Improve verifier log readability
@ 2021-12-15 19:22 Christy Lee
2021-12-15 19:22 ` [PATCH v2 bpf-next 1/3] Only print scratched registers and stack slots to verifier logs Christy Lee
` (2 more replies)
0 siblings, 3 replies; 10+ messages in thread
From: Christy Lee @ 2021-12-15 19:22 UTC (permalink / raw)
To: ast, daniel, andrii; +Cc: bpf, kernel-team, christylee, christyc.y.lee
Simplify verifier logs and improve readability.
Changelog:
----------
v1 -> v2:
v1: https://lore.kernel.org/bpf/20211213182117.682461-1-christylee@fb.com/
Patch 2/3:
* Verifier will skip insn_idx when the insn is longer than 8 bytes,
example:
0000000000000000 <good_prog>:
0: 18 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 r2 = 0 ll
2: 63 12 00 00 00 00 00 00 *(u32 *)(r2 + 0) = r1
3: 61 20 04 00 00 00 00 00 r0 = *(u32 *)(r2 + 4)
4: 95 00 00 00 00 00 00 00 exit
It's incorrect to check that prev_insn_idx = insn_idx - 1, skip this
check and print the verifier state on the correct line.
Before:
0: R1=ctx(id=0,off=0,imm=0) R10=fp0
; a[0] = (int)(long)ctx;
0: (18) r2 = 0xffffc900006de000
2: R2_w=map_value(id=0,off=0,ks=4,vs=16,imm=0)
2: (63) *(u32 *)(r2 +0) = r1
After:
0: R1=ctx(id=0,off=0,imm=0) R10=fp0
; a[0] = (int)(long)ctx;
0: (18) r2 = 0xffffc900006de000 ; R2_w=map_value(id=0,off=0,ks=4,vs=16,imm=0)
2: (63) *(u32 *)(r2 +0) = r1
* Track previous line logging length in env, allow aligning intsruction
from anywhere in the verifier
* Fixed bug where the verifier printed verifier state after checking
source memory access but before check destination memory access,
this ensures the aligned verifier state contains all scratched
registers
Patch 3/3:
* Added one more case where we should only log in log_level=2
Christy Lee (3):
Only print scratched registers and stack slots to verifier logs
Right align verifier states in verifier logs
Only output backtracking information in log level 2
include/linux/bpf_verifier.h | 10 +
kernel/bpf/verifier.c | 131 +++++++++--
.../testing/selftests/bpf/prog_tests/align.c | 214 +++++++++---------
3 files changed, 232 insertions(+), 123 deletions(-)
--
2.30.2
^ permalink raw reply [flat|nested] 10+ messages in thread* [PATCH v2 bpf-next 1/3] Only print scratched registers and stack slots to verifier logs 2021-12-15 19:22 [PATCH v2 bpf-next 0/3] Improve verifier log readability Christy Lee @ 2021-12-15 19:22 ` Christy Lee 2021-12-16 7:02 ` Andrii Nakryiko 2021-12-15 19:22 ` [PATCH v2 bpf-next 2/3] Right align verifier states in " Christy Lee 2021-12-15 19:22 ` [PATCH v2 bpf-next 3/3] Only output backtracking information in log level 2 Christy Lee 2 siblings, 1 reply; 10+ messages in thread From: Christy Lee @ 2021-12-15 19:22 UTC (permalink / raw) To: ast, daniel, andrii; +Cc: bpf, kernel-team, christylee, christyc.y.lee When printing verifier state for any log level, print full verifier state only on function calls or on errors. Otherwise, only print the registers and stack slots that were accessed. Log size differences: verif_scale_loop6 before: 234566564 verif_scale_loop6 after: 72143943 69% size reduction kfree_skb before: 166406 kfree_skb after: 55386 69% size reduction Before: 156: (61) r0 = *(u32 *)(r1 +0) 157: R0_w=invP(id=0,umax_value=4294967295,var_off=(0x0; 0xffffffff)) R1=ctx(id=0,off=0,imm=0) R2_w=invP0 R10=fp0 fp-8_w=00000000 fp-16_w=00\ 000000 fp-24_w=00000000 fp-32_w=00000000 fp-40_w=00000000 fp-48_w=00000000 fp-56_w=00000000 fp-64_w=00000000 fp-72_w=00000000 fp-80_w=00000\ 000 fp-88_w=00000000 fp-96_w=00000000 fp-104_w=00000000 fp-112_w=00000000 fp-120_w=00000000 fp-128_w=00000000 fp-136_w=00000000 fp-144_w=00\ 000000 fp-152_w=00000000 fp-160_w=00000000 fp-168_w=00000000 fp-176_w=00000000 fp-184_w=00000000 fp-192_w=00000000 fp-200_w=00000000 fp-208\ _w=00000000 fp-216_w=00000000 fp-224_w=00000000 fp-232_w=00000000 fp-240_w=00000000 fp-248_w=00000000 fp-256_w=00000000 fp-264_w=00000000 f\ p-272_w=00000000 fp-280_w=00000000 fp-288_w=00000000 fp-296_w=00000000 fp-304_w=00000000 fp-312_w=00000000 fp-320_w=00000000 fp-328_w=00000\ 000 fp-336_w=00000000 fp-344_w=00000000 fp-352_w=00000000 fp-360_w=00000000 fp-368_w=00000000 fp-376_w=00000000 fp-384_w=00000000 fp-392_w=\ 00000000 fp-400_w=00000000 fp-408_w=00000000 fp-416_w=00000000 fp-424_w=00000000 fp-432_w=00000000 fp-440_w=00000000 fp-448_w=00000000 ; return skb->len; 157: (95) exit Func#4 is safe for any args that match its prototype Validating get_constant() func#5... 158: R1=invP(id=0) R10=fp0 ; int get_constant(long val) 158: (bf) r0 = r1 159: R0_w=invP(id=1) R1=invP(id=1) R10=fp0 ; return val - 122; 159: (04) w0 += -122 160: R0_w=invP(id=0,umax_value=4294967295,var_off=(0x0; 0xffffffff)) R1=invP(id=1) R10=fp0 ; return val - 122; 160: (95) exit Func#5 is safe for any args that match its prototype Validating get_skb_ifindex() func#6... 161: R1=invP(id=0) R2=ctx(id=0,off=0,imm=0) R3=invP(id=0) R10=fp0 ; int get_skb_ifindex(int val, struct __sk_buff *skb, int var) 161: (bc) w0 = w3 162: R0_w=invP(id=0,umax_value=4294967295,var_off=(0x0; 0xffffffff)) R1=invP(id=0) R2=ctx(id=0,off=0,imm=0) R3=invP(id=0) R10=fp0 After: 156: (61) r0 = *(u32 *)(r1 +0) 157: R0_w=invP(id=0,umax_value=4294967295,var_off=(0x0; 0xffffffff)) R1=ctx(id=0,off=0,imm=0) ; return skb->len; 157: (95) exit Func#4 is safe for any args that match its prototype Validating get_constant() func#5... 158: R1=invP(id=0) R10=fp0 ; int get_constant(long val) 158: (bf) r0 = r1 159: R0_w=invP(id=1) R1=invP(id=1) ; return val - 122; 159: (04) w0 += -122 160: R0_w=invP(id=0,umax_value=4294967295,var_off=(0x0; 0xffffffff)) ; return val - 122; 160: (95) exit Func#5 is safe for any args that match its prototype Validating get_skb_ifindex() func#6... 161: R1=invP(id=0) R2=ctx(id=0,off=0,imm=0) R3=invP(id=0) R10=fp0 ; int get_skb_ifindex(int val, struct __sk_buff *skb, int var) 161: (bc) w0 = w3 162: R0_w=invP(id=0,umax_value=4294967295,var_off=(0x0; 0xffffffff)) R3=invP(id=0) Signed-off-by: Christy Lee <christylee@fb.com> --- include/linux/bpf_verifier.h | 7 +++ kernel/bpf/verifier.c | 62 ++++++++++++++++++- .../testing/selftests/bpf/prog_tests/align.c | 30 ++++----- 3 files changed, 82 insertions(+), 17 deletions(-) diff --git a/include/linux/bpf_verifier.h b/include/linux/bpf_verifier.h index 182b16a91084..c555222c97d6 100644 --- a/include/linux/bpf_verifier.h +++ b/include/linux/bpf_verifier.h @@ -474,6 +474,13 @@ struct bpf_verifier_env { /* longest register parentage chain walked for liveness marking */ u32 longest_mark_read_walk; bpfptr_t fd_array; + + /* bit mask to keep track of whether a register has been accessed + * since the last time the function state was pritned + */ + u32 scratched_regs; + /* Same as scratched_regs but for stack slots */ + u64 scratched_stack_slots; }; __printf(2, 0) void bpf_verifier_vlog(struct bpf_verifier_log *log, diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c index d74e8a99412e..f4228864a3e9 100644 --- a/kernel/bpf/verifier.c +++ b/kernel/bpf/verifier.c @@ -608,6 +608,44 @@ static const char *kernel_type_name(const struct btf* btf, u32 id) return btf_name_by_offset(btf, btf_type_by_id(btf, id)->name_off); } +static void mark_reg_scratched(struct bpf_verifier_env *env, u32 regno) +{ + env->scratched_regs |= 1U << regno; +} + +static void mark_stack_slot_scratched(struct bpf_verifier_env *env, u32 spi) +{ + env->scratched_stack_slots |= 1UL << spi; +} + +static bool reg_scratched(const struct bpf_verifier_env *env, u32 regno) +{ + return (env->scratched_regs >> regno) & 1; +} + +static bool stack_slot_scratched(const struct bpf_verifier_env *env, u64 regno) +{ + return (env->scratched_stack_slots >> regno) & 1; +} + +static bool verifier_state_scratched(const struct bpf_verifier_env *env) +{ + return env->scratched_regs || env->scratched_stack_slots; +} + +static void mark_verifier_state_clean(struct bpf_verifier_env *env) +{ + env->scratched_regs = 0U; + env->scratched_stack_slots = 0UL; +} + +/* Used for printing the entire verifier state. */ +static void mark_verifier_state_scratched(struct bpf_verifier_env *env) +{ + env->scratched_regs = ~0U; + env->scratched_stack_slots = ~0UL; +} + /* The reg state of a pointer or a bounded scalar was saved when * it was spilled to the stack. */ @@ -636,6 +674,8 @@ static void print_verifier_state(struct bpf_verifier_env *env, t = reg->type; if (t == NOT_INIT) continue; + if (!reg_scratched(env, i)) + continue; verbose(env, " R%d", i); print_liveness(env, reg->live); verbose(env, "=%s", reg_type_str[t]); @@ -725,6 +765,8 @@ static void print_verifier_state(struct bpf_verifier_env *env, types_buf[BPF_REG_SIZE] = 0; if (!valid) continue; + if (!stack_slot_scratched(env, i)) + continue; verbose(env, " fp%d", (-i - 1) * BPF_REG_SIZE); print_liveness(env, state->stack[i].spilled_ptr.live); if (is_spilled_reg(&state->stack[i])) { @@ -750,6 +792,7 @@ static void print_verifier_state(struct bpf_verifier_env *env, if (state->in_async_callback_fn) verbose(env, " async_cb"); verbose(env, "\n"); + mark_verifier_state_clean(env); } /* copy array src of length n * size bytes to dst. dst is reallocated if it's too @@ -1540,6 +1583,7 @@ static void init_func_state(struct bpf_verifier_env *env, state->frameno = frameno; state->subprogno = subprogno; init_reg_state(env, state); + mark_verifier_state_scratched(env); } /* Similar to push_stack(), but for async callbacks */ @@ -2227,6 +2271,8 @@ static int check_reg_arg(struct bpf_verifier_env *env, u32 regno, return -EINVAL; } + mark_reg_scratched(env, regno); + reg = ®s[regno]; rw64 = is_reg64(env, insn, regno, reg, t); if (t == SRC_OP) { @@ -2836,6 +2882,7 @@ static int check_stack_write_fixed_off(struct bpf_verifier_env *env, env->insn_aux_data[insn_idx].sanitize_stack_spill = true; } + mark_stack_slot_scratched(env, spi); if (reg && !(off % BPF_REG_SIZE) && register_is_bounded(reg) && !register_is_null(reg) && env->bpf_capable) { if (dst_reg != BPF_REG_FP) { @@ -2957,6 +3004,7 @@ static int check_stack_write_var_off(struct bpf_verifier_env *env, slot = -i - 1; spi = slot / BPF_REG_SIZE; stype = &state->stack[spi].slot_type[slot % BPF_REG_SIZE]; + mark_stack_slot_scratched(env, spi); if (!env->allow_ptr_leaks && *stype != NOT_INIT @@ -6009,8 +6057,10 @@ static int __check_func_call(struct bpf_verifier_env *env, struct bpf_insn *insn *insn_idx = env->subprog_info[subprog].start - 1; if (env->log.level & BPF_LOG_LEVEL) { + mark_verifier_state_scratched(env); verbose(env, "caller:\n"); print_verifier_state(env, caller); + mark_verifier_state_scratched(env); verbose(env, "callee:\n"); print_verifier_state(env, callee); } @@ -6226,8 +6276,10 @@ static int prepare_func_exit(struct bpf_verifier_env *env, int *insn_idx) *insn_idx = callee->callsite + 1; if (env->log.level & BPF_LOG_LEVEL) { + mark_verifier_state_scratched(env); verbose(env, "returning from callee:\n"); print_verifier_state(env, callee); + mark_verifier_state_scratched(env); verbose(env, "to caller at %d:\n", *insn_idx); print_verifier_state(env, caller); } @@ -8248,11 +8300,13 @@ static int adjust_reg_min_max_vals(struct bpf_verifier_env *env, /* Got here implies adding two SCALAR_VALUEs */ if (WARN_ON_ONCE(ptr_reg)) { + mark_verifier_state_scratched(env); print_verifier_state(env, state); verbose(env, "verifier internal error: unexpected ptr_reg\n"); return -EINVAL; } if (WARN_ON(!src_reg)) { + mark_verifier_state_scratched(env); print_verifier_state(env, state); verbose(env, "verifier internal error: no src_reg\n"); return -EINVAL; @@ -11256,9 +11310,10 @@ static int do_check(struct bpf_verifier_env *env) if (need_resched()) cond_resched(); - if (env->log.level & BPF_LOG_LEVEL2 || + if ((env->log.level & BPF_LOG_LEVEL2) || (env->log.level & BPF_LOG_LEVEL && do_print_state)) { - if (env->log.level & BPF_LOG_LEVEL2) + if (verifier_state_scratched(env) && + (env->log.level & BPF_LOG_LEVEL2)) verbose(env, "%d:", env->insn_idx); else verbose(env, "\nfrom %d to %d%s:", @@ -11487,6 +11542,7 @@ static int do_check(struct bpf_verifier_env *env) if (err) return err; process_bpf_exit: + mark_verifier_state_scratched(env); update_branch_counts(env, env->cur_state); err = pop_stack(env, &prev_insn_idx, &env->insn_idx, pop_log); @@ -14147,6 +14203,8 @@ int bpf_check(struct bpf_prog **prog, union bpf_attr *attr, bpfptr_t uattr) } } + mark_verifier_state_clean(env); + if (IS_ERR(btf_vmlinux)) { /* Either gcc or pahole or kernel are broken. */ verbose(env, "in-kernel BTF is malformed\n"); diff --git a/tools/testing/selftests/bpf/prog_tests/align.c b/tools/testing/selftests/bpf/prog_tests/align.c index 837f67c6bfda..aeb2080a67f7 100644 --- a/tools/testing/selftests/bpf/prog_tests/align.c +++ b/tools/testing/selftests/bpf/prog_tests/align.c @@ -39,8 +39,8 @@ static struct bpf_align_test tests[] = { }, .prog_type = BPF_PROG_TYPE_SCHED_CLS, .matches = { - {1, "R1=ctx(id=0,off=0,imm=0)"}, - {1, "R10=fp0"}, + {0, "R1=ctx(id=0,off=0,imm=0)"}, + {0, "R10=fp0"}, {1, "R3_w=inv2"}, {2, "R3_w=inv4"}, {3, "R3_w=inv8"}, @@ -67,8 +67,8 @@ static struct bpf_align_test tests[] = { }, .prog_type = BPF_PROG_TYPE_SCHED_CLS, .matches = { - {1, "R1=ctx(id=0,off=0,imm=0)"}, - {1, "R10=fp0"}, + {0, "R1=ctx(id=0,off=0,imm=0)"}, + {0, "R10=fp0"}, {1, "R3_w=inv1"}, {2, "R3_w=inv2"}, {3, "R3_w=inv4"}, @@ -96,8 +96,8 @@ static struct bpf_align_test tests[] = { }, .prog_type = BPF_PROG_TYPE_SCHED_CLS, .matches = { - {1, "R1=ctx(id=0,off=0,imm=0)"}, - {1, "R10=fp0"}, + {0, "R1=ctx(id=0,off=0,imm=0)"}, + {0, "R10=fp0"}, {1, "R3_w=inv4"}, {2, "R3_w=inv8"}, {3, "R3_w=inv10"}, @@ -118,8 +118,8 @@ static struct bpf_align_test tests[] = { }, .prog_type = BPF_PROG_TYPE_SCHED_CLS, .matches = { - {1, "R1=ctx(id=0,off=0,imm=0)"}, - {1, "R10=fp0"}, + {0, "R1=ctx(id=0,off=0,imm=0)"}, + {0, "R10=fp0"}, {1, "R3_w=inv7"}, {2, "R3_w=inv7"}, {3, "R3_w=inv14"}, @@ -161,13 +161,13 @@ static struct bpf_align_test tests[] = { }, .prog_type = BPF_PROG_TYPE_SCHED_CLS, .matches = { - {7, "R0_w=pkt(id=0,off=8,r=8,imm=0)"}, + {6, "R0_w=pkt(id=0,off=8,r=8,imm=0)"}, {7, "R3_w=inv(id=0,umax_value=255,var_off=(0x0; 0xff))"}, {8, "R3_w=inv(id=0,umax_value=510,var_off=(0x0; 0x1fe))"}, {9, "R3_w=inv(id=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, {10, "R3_w=inv(id=0,umax_value=2040,var_off=(0x0; 0x7f8))"}, {11, "R3_w=inv(id=0,umax_value=4080,var_off=(0x0; 0xff0))"}, - {18, "R3=pkt_end(id=0,off=0,imm=0)"}, + {13, "R3_w=pkt_end(id=0,off=0,imm=0)"}, {18, "R4_w=inv(id=0,umax_value=255,var_off=(0x0; 0xff))"}, {19, "R4_w=inv(id=0,umax_value=8160,var_off=(0x0; 0x1fe0))"}, {20, "R4_w=inv(id=0,umax_value=4080,var_off=(0x0; 0xff0))"}, @@ -234,10 +234,10 @@ static struct bpf_align_test tests[] = { }, .prog_type = BPF_PROG_TYPE_SCHED_CLS, .matches = { - {4, "R5_w=pkt(id=0,off=0,r=0,imm=0)"}, + {3, "R5_w=pkt(id=0,off=0,r=0,imm=0)"}, {5, "R5_w=pkt(id=0,off=14,r=0,imm=0)"}, {6, "R4_w=pkt(id=0,off=14,r=0,imm=0)"}, - {10, "R2=pkt(id=0,off=0,r=18,imm=0)"}, + {9, "R2=pkt(id=0,off=0,r=18,imm=0)"}, {10, "R5=pkt(id=0,off=14,r=18,imm=0)"}, {10, "R4_w=inv(id=0,umax_value=255,var_off=(0x0; 0xff))"}, {14, "R4_w=inv(id=0,umax_value=65535,var_off=(0x0; 0xffff))"}, @@ -296,7 +296,7 @@ static struct bpf_align_test tests[] = { /* Calculated offset in R6 has unknown value, but known * alignment of 4. */ - {8, "R2_w=pkt(id=0,off=0,r=8,imm=0)"}, + {6, "R2_w=pkt(id=0,off=0,r=8,imm=0)"}, {8, "R6_w=inv(id=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, /* Offset is added to packet pointer R5, resulting in * known fixed offset, and variable offset from R6. @@ -386,7 +386,7 @@ static struct bpf_align_test tests[] = { /* Calculated offset in R6 has unknown value, but known * alignment of 4. */ - {8, "R2_w=pkt(id=0,off=0,r=8,imm=0)"}, + {6, "R2_w=pkt(id=0,off=0,r=8,imm=0)"}, {8, "R6_w=inv(id=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, /* Adding 14 makes R6 be (4n+2) */ {9, "R6_w=inv(id=0,umin_value=14,umax_value=1034,var_off=(0x2; 0x7fc))"}, @@ -458,7 +458,7 @@ static struct bpf_align_test tests[] = { /* Checked s>=0 */ {9, "R5=inv(id=0,umin_value=2,umax_value=9223372036854775806,var_off=(0x2; 0x7ffffffffffffffc)"}, /* packet pointer + nonnegative (4n+2) */ - {11, "R6_w=pkt(id=1,off=0,r=0,umin_value=2,umax_value=9223372036854775806,var_off=(0x2; 0x7ffffffffffffffc)"}, + {12, "R6_w=pkt(id=1,off=0,r=0,umin_value=2,umax_value=9223372036854775806,var_off=(0x2; 0x7ffffffffffffffc)"}, {13, "R4_w=pkt(id=1,off=4,r=0,umin_value=2,umax_value=9223372036854775806,var_off=(0x2; 0x7ffffffffffffffc)"}, /* NET_IP_ALIGN + (4n+2) == (4n), alignment is fine. * We checked the bounds, but it might have been able -- 2.30.2 ^ permalink raw reply related [flat|nested] 10+ messages in thread
* Re: [PATCH v2 bpf-next 1/3] Only print scratched registers and stack slots to verifier logs 2021-12-15 19:22 ` [PATCH v2 bpf-next 1/3] Only print scratched registers and stack slots to verifier logs Christy Lee @ 2021-12-16 7:02 ` Andrii Nakryiko [not found] ` <CAPqJDZpuZ586TawooQhxZGvOqgF4yCjT0yOLEXAUer8eJDO7gw@mail.gmail.com> 0 siblings, 1 reply; 10+ messages in thread From: Andrii Nakryiko @ 2021-12-16 7:02 UTC (permalink / raw) To: Christy Lee Cc: Alexei Starovoitov, Daniel Borkmann, Andrii Nakryiko, bpf, Kernel Team, christyc.y.lee On Wed, Dec 15, 2021 at 11:23 AM Christy Lee <christylee@fb.com> wrote: > > When printing verifier state for any log level, print full verifier > state only on function calls or on errors. Otherwise, only print the > registers and stack slots that were accessed. > > Log size differences: > > verif_scale_loop6 before: 234566564 > verif_scale_loop6 after: 72143943 > 69% size reduction > > kfree_skb before: 166406 > kfree_skb after: 55386 > 69% size reduction > > Before: > > 156: (61) r0 = *(u32 *)(r1 +0) > 157: R0_w=invP(id=0,umax_value=4294967295,var_off=(0x0; 0xffffffff)) R1=ctx(id=0,off=0,imm=0) R2_w=invP0 R10=fp0 fp-8_w=00000000 fp-16_w=00\ > 000000 fp-24_w=00000000 fp-32_w=00000000 fp-40_w=00000000 fp-48_w=00000000 fp-56_w=00000000 fp-64_w=00000000 fp-72_w=00000000 fp-80_w=00000\ > 000 fp-88_w=00000000 fp-96_w=00000000 fp-104_w=00000000 fp-112_w=00000000 fp-120_w=00000000 fp-128_w=00000000 fp-136_w=00000000 fp-144_w=00\ > 000000 fp-152_w=00000000 fp-160_w=00000000 fp-168_w=00000000 fp-176_w=00000000 fp-184_w=00000000 fp-192_w=00000000 fp-200_w=00000000 fp-208\ > _w=00000000 fp-216_w=00000000 fp-224_w=00000000 fp-232_w=00000000 fp-240_w=00000000 fp-248_w=00000000 fp-256_w=00000000 fp-264_w=00000000 f\ > p-272_w=00000000 fp-280_w=00000000 fp-288_w=00000000 fp-296_w=00000000 fp-304_w=00000000 fp-312_w=00000000 fp-320_w=00000000 fp-328_w=00000\ > 000 fp-336_w=00000000 fp-344_w=00000000 fp-352_w=00000000 fp-360_w=00000000 fp-368_w=00000000 fp-376_w=00000000 fp-384_w=00000000 fp-392_w=\ > 00000000 fp-400_w=00000000 fp-408_w=00000000 fp-416_w=00000000 fp-424_w=00000000 fp-432_w=00000000 fp-440_w=00000000 fp-448_w=00000000 > ; return skb->len; > 157: (95) exit > Func#4 is safe for any args that match its prototype > Validating get_constant() func#5... > 158: R1=invP(id=0) R10=fp0 > ; int get_constant(long val) > 158: (bf) r0 = r1 > 159: R0_w=invP(id=1) R1=invP(id=1) R10=fp0 > ; return val - 122; > 159: (04) w0 += -122 > 160: R0_w=invP(id=0,umax_value=4294967295,var_off=(0x0; 0xffffffff)) R1=invP(id=1) R10=fp0 > ; return val - 122; > 160: (95) exit > Func#5 is safe for any args that match its prototype > Validating get_skb_ifindex() func#6... > 161: R1=invP(id=0) R2=ctx(id=0,off=0,imm=0) R3=invP(id=0) R10=fp0 > ; int get_skb_ifindex(int val, struct __sk_buff *skb, int var) > 161: (bc) w0 = w3 > 162: R0_w=invP(id=0,umax_value=4294967295,var_off=(0x0; 0xffffffff)) R1=invP(id=0) R2=ctx(id=0,off=0,imm=0) R3=invP(id=0) R10=fp0 > > After: > > 156: (61) r0 = *(u32 *)(r1 +0) > 157: R0_w=invP(id=0,umax_value=4294967295,var_off=(0x0; 0xffffffff)) R1=ctx(id=0,off=0,imm=0) > ; return skb->len; > 157: (95) exit > Func#4 is safe for any args that match its prototype > Validating get_constant() func#5... > 158: R1=invP(id=0) R10=fp0 > ; int get_constant(long val) > 158: (bf) r0 = r1 > 159: R0_w=invP(id=1) R1=invP(id=1) > ; return val - 122; > 159: (04) w0 += -122 > 160: R0_w=invP(id=0,umax_value=4294967295,var_off=(0x0; 0xffffffff)) > ; return val - 122; > 160: (95) exit > Func#5 is safe for any args that match its prototype > Validating get_skb_ifindex() func#6... > 161: R1=invP(id=0) R2=ctx(id=0,off=0,imm=0) R3=invP(id=0) R10=fp0 > ; int get_skb_ifindex(int val, struct __sk_buff *skb, int var) > 161: (bc) w0 = w3 > 162: R0_w=invP(id=0,umax_value=4294967295,var_off=(0x0; 0xffffffff)) R3=invP(id=0) > > Signed-off-by: Christy Lee <christylee@fb.com> > --- Looks good to me, but see a few nits below. They can be ignored or addressed as a follow up. Acked-by: Andrii Nakryiko <andrii@kernel.org> > include/linux/bpf_verifier.h | 7 +++ > kernel/bpf/verifier.c | 62 ++++++++++++++++++- > .../testing/selftests/bpf/prog_tests/align.c | 30 ++++----- > 3 files changed, 82 insertions(+), 17 deletions(-) > > diff --git a/include/linux/bpf_verifier.h b/include/linux/bpf_verifier.h > index 182b16a91084..c555222c97d6 100644 > --- a/include/linux/bpf_verifier.h > +++ b/include/linux/bpf_verifier.h > @@ -474,6 +474,13 @@ struct bpf_verifier_env { > /* longest register parentage chain walked for liveness marking */ > u32 longest_mark_read_walk; > bpfptr_t fd_array; > + > + /* bit mask to keep track of whether a register has been accessed > + * since the last time the function state was pritned typo: printed > + */ > + u32 scratched_regs; > + /* Same as scratched_regs but for stack slots */ > + u64 scratched_stack_slots; > }; > > __printf(2, 0) void bpf_verifier_vlog(struct bpf_verifier_log *log, [...] > + mark_stack_slot_scratched(env, spi); > if (reg && !(off % BPF_REG_SIZE) && register_is_bounded(reg) && > !register_is_null(reg) && env->bpf_capable) { > if (dst_reg != BPF_REG_FP) { > @@ -2957,6 +3004,7 @@ static int check_stack_write_var_off(struct bpf_verifier_env *env, > slot = -i - 1; > spi = slot / BPF_REG_SIZE; > stype = &state->stack[spi].slot_type[slot % BPF_REG_SIZE]; > + mark_stack_slot_scratched(env, spi); > > if (!env->allow_ptr_leaks > && *stype != NOT_INIT > @@ -6009,8 +6057,10 @@ static int __check_func_call(struct bpf_verifier_env *env, struct bpf_insn *insn > *insn_idx = env->subprog_info[subprog].start - 1; > > if (env->log.level & BPF_LOG_LEVEL) { > + mark_verifier_state_scratched(env); > verbose(env, "caller:\n"); > print_verifier_state(env, caller); In all but one cases you call mark_verifier_state_scratched(env) before calling print_verifier_state(). Instead of sort of artificially scratch entire state, I'd add a bool flag to print_verifier_state() to control whether we want to take into account scratch masks or not. It would also make sure that we will never forget to scratch it where necessary (you'll have to make a conscious decision on each print_verifier_state() call). > + mark_verifier_state_scratched(env); > verbose(env, "callee:\n"); > print_verifier_state(env, callee); > } [...] > @@ -161,13 +161,13 @@ static struct bpf_align_test tests[] = { > }, > .prog_type = BPF_PROG_TYPE_SCHED_CLS, > .matches = { > - {7, "R0_w=pkt(id=0,off=8,r=8,imm=0)"}, > + {6, "R0_w=pkt(id=0,off=8,r=8,imm=0)"}, > {7, "R3_w=inv(id=0,umax_value=255,var_off=(0x0; 0xff))"}, > {8, "R3_w=inv(id=0,umax_value=510,var_off=(0x0; 0x1fe))"}, > {9, "R3_w=inv(id=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, > {10, "R3_w=inv(id=0,umax_value=2040,var_off=(0x0; 0x7f8))"}, > {11, "R3_w=inv(id=0,umax_value=4080,var_off=(0x0; 0xff0))"}, consider this a feature request (unless people disagree), but these "_value" suffixes for umin/umax/s32_min/etc are just noise and don't contribute anything but extra visual noise. I'd remove them. map_value is ok, probably (because we should have map_key, I guess). > - {18, "R3=pkt_end(id=0,off=0,imm=0)"}, > + {13, "R3_w=pkt_end(id=0,off=0,imm=0)"}, > {18, "R4_w=inv(id=0,umax_value=255,var_off=(0x0; 0xff))"}, > {19, "R4_w=inv(id=0,umax_value=8160,var_off=(0x0; 0x1fe0))"}, > {20, "R4_w=inv(id=0,umax_value=4080,var_off=(0x0; 0xff0))"}, > @@ -234,10 +234,10 @@ static struct bpf_align_test tests[] = { > }, > .prog_type = BPF_PROG_TYPE_SCHED_CLS, > .matches = { > - {4, "R5_w=pkt(id=0,off=0,r=0,imm=0)"}, > + {3, "R5_w=pkt(id=0,off=0,r=0,imm=0)"}, another improvement suggestion: all these id=0 is also noise. I'd make sure that cases where we do care about ids always use id > 0 (I think that might be the case already) and just never output id=0 > {5, "R5_w=pkt(id=0,off=14,r=0,imm=0)"}, > {6, "R4_w=pkt(id=0,off=14,r=0,imm=0)"}, > - {10, "R2=pkt(id=0,off=0,r=18,imm=0)"}, > + {9, "R2=pkt(id=0,off=0,r=18,imm=0)"}, > {10, "R5=pkt(id=0,off=14,r=18,imm=0)"}, > {10, "R4_w=inv(id=0,umax_value=255,var_off=(0x0; 0xff))"}, > {14, "R4_w=inv(id=0,umax_value=65535,var_off=(0x0; 0xffff))"}, Another thing that always confuses me is the use of "inv" to denote scalar. I could never understand why it's not a "scalar" or just nothing. Especially for cases when we have known value. We'll see "R4=inv4". So confusing. Maybe let's just drop the inv, so we'll have: R4=4 or (taking into the account all the above suggestions) R4=(umax=65535,var_off=(0x0; 0xffff)) I don't think we lose anything by dropping "inv", but "scalar" would be still better (even if slightly longer). > @@ -296,7 +296,7 @@ static struct bpf_align_test tests[] = { > /* Calculated offset in R6 has unknown value, but known > * alignment of 4. > */ > - {8, "R2_w=pkt(id=0,off=0,r=8,imm=0)"}, > + {6, "R2_w=pkt(id=0,off=0,r=8,imm=0)"}, > {8, "R6_w=inv(id=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, > /* Offset is added to packet pointer R5, resulting in > * known fixed offset, and variable offset from R6. [...] ^ permalink raw reply [flat|nested] 10+ messages in thread
[parent not found: <CAPqJDZpuZ586TawooQhxZGvOqgF4yCjT0yOLEXAUer8eJDO7gw@mail.gmail.com>]
* Re: [PATCH v2 bpf-next 1/3] Only print scratched registers and stack slots to verifier logs [not found] ` <CAPqJDZpuZ586TawooQhxZGvOqgF4yCjT0yOLEXAUer8eJDO7gw@mail.gmail.com> @ 2021-12-16 16:02 ` Christy Lee 0 siblings, 0 replies; 10+ messages in thread From: Christy Lee @ 2021-12-16 16:02 UTC (permalink / raw) To: Andrii Nakryiko Cc: Christy Lee, Alexei Starovoitov, Daniel Borkmann, Andrii Nakryiko, bpf, Kernel Team On Thu, Dec 16, 2021 at 7:48 AM Christy Lee <christyc.y.lee@gmail.com> wrote: Apologies, resending this because the previous email was not plain text. > > > On Wed, Dec 15, 2021 at 11:02 PM Andrii Nakryiko <andrii.nakryiko@gmail.com> wrote: >> >> On Wed, Dec 15, 2021 at 11:23 AM Christy Lee <christylee@fb.com> wrote: >> > [...] >> >> >> Looks good to me, but see a few nits below. They can be ignored or >> addressed as a follow up. >> >> >> Acked-by: Andrii Nakryiko <andrii@kernel.org> >> >> > include/linux/bpf_verifier.h | 7 +++ >> > kernel/bpf/verifier.c | 62 ++++++++++++++++++- >> > .../testing/selftests/bpf/prog_tests/align.c | 30 ++++----- >> > 3 files changed, 82 insertions(+), 17 deletions(-) >> > >> > diff --git a/include/linux/bpf_verifier.h b/include/linux/bpf_verifier.h >> > index 182b16a91084..c555222c97d6 100644 >> > --- a/include/linux/bpf_verifier.h >> > +++ b/include/linux/bpf_verifier.h >> > @@ -474,6 +474,13 @@ struct bpf_verifier_env { >> > /* longest register parentage chain walked for liveness marking */ >> > u32 longest_mark_read_walk; >> > bpfptr_t fd_array; >> > + >> > + /* bit mask to keep track of whether a register has been accessed >> > + * since the last time the function state was pritned >> >> typo: printed >> >> > + */ >> > + u32 scratched_regs; >> > + /* Same as scratched_regs but for stack slots */ >> > + u64 scratched_stack_slots; >> > }; >> > >> > __printf(2, 0) void bpf_verifier_vlog(struct bpf_verifier_log *log, >> >> [...] >> >> > + mark_stack_slot_scratched(env, spi); >> > if (reg && !(off % BPF_REG_SIZE) && register_is_bounded(reg) && >> > !register_is_null(reg) && env->bpf_capable) { >> > if (dst_reg != BPF_REG_FP) { >> > @@ -2957,6 +3004,7 @@ static int check_stack_write_var_off(struct bpf_verifier_env *env, >> > slot = -i - 1; >> > spi = slot / BPF_REG_SIZE; >> > stype = &state->stack[spi].slot_type[slot % BPF_REG_SIZE]; >> > + mark_stack_slot_scratched(env, spi); >> > >> > if (!env->allow_ptr_leaks >> > && *stype != NOT_INIT >> > @@ -6009,8 +6057,10 @@ static int __check_func_call(struct bpf_verifier_env *env, struct bpf_insn *insn >> > *insn_idx = env->subprog_info[subprog].start - 1; >> > >> > if (env->log.level & BPF_LOG_LEVEL) { >> > + mark_verifier_state_scratched(env); >> > verbose(env, "caller:\n"); >> > print_verifier_state(env, caller); >> >> In all but one cases you call mark_verifier_state_scratched(env) >> before calling print_verifier_state(). Instead of sort of artificially >> scratch entire state, I'd add a bool flag to print_verifier_state() to >> control whether we want to take into account scratch masks or not. It >> would also make sure that we will never forget to scratch it where >> necessary (you'll have to make a conscious decision on each >> print_verifier_state() call). > > Good idea! I'll do that. >> >> >> > + mark_verifier_state_scratched(env); >> > verbose(env, "callee:\n"); >> > print_verifier_state(env, callee); >> > } >> >> [...] >> >> > @@ -161,13 +161,13 @@ static struct bpf_align_test tests[] = { >> > }, >> > .prog_type = BPF_PROG_TYPE_SCHED_CLS, >> > .matches = { >> > - {7, "R0_w=pkt(id=0,off=8,r=8,imm=0)"}, >> > + {6, "R0_w=pkt(id=0,off=8,r=8,imm=0)"}, >> > {7, "R3_w=inv(id=0,umax_value=255,var_off=(0x0; 0xff))"}, >> > {8, "R3_w=inv(id=0,umax_value=510,var_off=(0x0; 0x1fe))"}, >> > {9, "R3_w=inv(id=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, >> > {10, "R3_w=inv(id=0,umax_value=2040,var_off=(0x0; 0x7f8))"}, >> > {11, "R3_w=inv(id=0,umax_value=4080,var_off=(0x0; 0xff0))"}, >> > These would be very useful features, I'll address them as a follow up. >> >> consider this a feature request (unless people disagree), but these >> "_value" suffixes for umin/umax/s32_min/etc are just noise and don't >> contribute anything but extra visual noise. I'd remove them. map_value >> is ok, probably (because we should have map_key, I guess). >> >> > - {18, "R3=pkt_end(id=0,off=0,imm=0)"}, >> > + {13, "R3_w=pkt_end(id=0,off=0,imm=0)"}, >> > {18, "R4_w=inv(id=0,umax_value=255,var_off=(0x0; 0xff))"}, >> > {19, "R4_w=inv(id=0,umax_value=8160,var_off=(0x0; 0x1fe0))"}, >> > {20, "R4_w=inv(id=0,umax_value=4080,var_off=(0x0; 0xff0))"}, >> > @@ -234,10 +234,10 @@ static struct bpf_align_test tests[] = { >> > }, >> > .prog_type = BPF_PROG_TYPE_SCHED_CLS, >> > .matches = { >> > - {4, "R5_w=pkt(id=0,off=0,r=0,imm=0)"}, >> > + {3, "R5_w=pkt(id=0,off=0,r=0,imm=0)"}, >> >> another improvement suggestion: all these id=0 is also noise. I'd make >> sure that cases where we do care about ids always use id > 0 (I think >> that might be the case already) and just never output id=0 >> >> >> > {5, "R5_w=pkt(id=0,off=14,r=0,imm=0)"}, >> > {6, "R4_w=pkt(id=0,off=14,r=0,imm=0)"}, >> > - {10, "R2=pkt(id=0,off=0,r=18,imm=0)"}, >> > + {9, "R2=pkt(id=0,off=0,r=18,imm=0)"}, >> > {10, "R5=pkt(id=0,off=14,r=18,imm=0)"}, >> > {10, "R4_w=inv(id=0,umax_value=255,var_off=(0x0; 0xff))"}, >> > {14, "R4_w=inv(id=0,umax_value=65535,var_off=(0x0; 0xffff))"}, >> >> Another thing that always confuses me is the use of "inv" to denote >> scalar. I could never understand why it's not a "scalar" or just >> nothing. Especially for cases when we have known value. We'll see >> "R4=inv4". So confusing. Maybe let's just drop the inv, so we'll have: >> >> R4=4 >> >> or (taking into the account all the above suggestions) >> >> R4=(umax=65535,var_off=(0x0; 0xffff)) >> >> I don't think we lose anything by dropping "inv", but "scalar" would >> be still better (even if slightly longer). >> >> >> > @@ -296,7 +296,7 @@ static struct bpf_align_test tests[] = { >> > /* Calculated offset in R6 has unknown value, but known >> > * alignment of 4. >> > */ >> > - {8, "R2_w=pkt(id=0,off=0,r=8,imm=0)"}, >> > + {6, "R2_w=pkt(id=0,off=0,r=8,imm=0)"}, >> > {8, "R6_w=inv(id=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, >> > /* Offset is added to packet pointer R5, resulting in >> > * known fixed offset, and variable offset from R6. >> >> [...] ^ permalink raw reply [flat|nested] 10+ messages in thread
* [PATCH v2 bpf-next 2/3] Right align verifier states in verifier logs 2021-12-15 19:22 [PATCH v2 bpf-next 0/3] Improve verifier log readability Christy Lee 2021-12-15 19:22 ` [PATCH v2 bpf-next 1/3] Only print scratched registers and stack slots to verifier logs Christy Lee @ 2021-12-15 19:22 ` Christy Lee 2021-12-16 7:02 ` Andrii Nakryiko 2021-12-15 19:22 ` [PATCH v2 bpf-next 3/3] Only output backtracking information in log level 2 Christy Lee 2 siblings, 1 reply; 10+ messages in thread From: Christy Lee @ 2021-12-15 19:22 UTC (permalink / raw) To: ast, daniel, andrii; +Cc: bpf, kernel-team, christylee, christyc.y.lee Make the verifier logs more readable, print the verifier states on the corresponding instruction line. If the previous line was not a bpf instruction, then print the verifier states on its own line. Before: Validating test_pkt_access_subprog3() func#3... 86: R1=invP(id=0) R2=ctx(id=0,off=0,imm=0) R10=fp0 ; int test_pkt_access_subprog3(int val, struct __sk_buff *skb) 86: (bf) r6 = r2 87: R2=ctx(id=0,off=0,imm=0) R6_w=ctx(id=0,off=0,imm=0) 87: (bc) w7 = w1 88: R1=invP(id=0) R7_w=invP(id=0,umax_value=4294967295,var_off=(0x0; 0xffffffff)) ; return get_skb_len(skb) * get_skb_ifindex(val, skb, get_constant(123)); 88: (bf) r1 = r6 89: R1_w=ctx(id=0,off=0,imm=0) R6_w=ctx(id=0,off=0,imm=0) 89: (85) call pc+9 Func#4 is global and valid. Skipping. 90: R0_w=invP(id=0) 90: (bc) w8 = w0 91: R0_w=invP(id=0) R8_w=invP(id=0,umax_value=4294967295,var_off=(0x0; 0xffffffff)) ; return get_skb_len(skb) * get_skb_ifindex(val, skb, get_constant(123)); 91: (b7) r1 = 123 92: R1_w=invP123 92: (85) call pc+65 Func#5 is global and valid. Skipping. 93: R0=invP(id=0) After: Validating test_pkt_access_subprog3() func#3... 86: R1=invP(id=0) R2=ctx(id=0,off=0,imm=0) R10=fp0 ; int test_pkt_access_subprog3(int val, struct __sk_buff *skb) 86: (bf) r6 = r2 ; R2=ctx(id=0,off=0,imm=0) R6_w=ctx(id=0,off=0,imm=0) 87: (bc) w7 = w1 ; R1=invP(id=0) R7_w=invP(id=0,umax_value=4294967295,var_off=(0x0; 0xffffffff)) ; return get_skb_len(skb) * get_skb_ifindex(val, skb, get_constant(123)); 88: (bf) r1 = r6 ; R1_w=ctx(id=0,off=0,imm=0) R6_w=ctx(id=0,off=0,imm=0) 89: (85) call pc+9 Func#4 is global and valid. Skipping. 90: R0_w=invP(id=0) 90: (bc) w8 = w0 ; R0_w=invP(id=0) R8_w=invP(id=0,umax_value=4294967295,var_off=(0x0; 0xffffffff)) ; return get_skb_len(skb) * get_skb_ifindex(val, skb, get_constant(123)); 91: (b7) r1 = 123 ; R1_w=invP123 92: (85) call pc+65 Func#5 is global and valid. Skipping. 93: R0=invP(id=0) Signed-off-by: Christy Lee <christylee@fb.com> --- include/linux/bpf_verifier.h | 3 + kernel/bpf/verifier.c | 69 ++++-- .../testing/selftests/bpf/prog_tests/align.c | 196 ++++++++++-------- 3 files changed, 156 insertions(+), 112 deletions(-) diff --git a/include/linux/bpf_verifier.h b/include/linux/bpf_verifier.h index c555222c97d6..cf5801c02216 100644 --- a/include/linux/bpf_verifier.h +++ b/include/linux/bpf_verifier.h @@ -388,6 +388,8 @@ static inline bool bpf_verifier_log_full(const struct bpf_verifier_log *log) #define BPF_LOG_LEVEL (BPF_LOG_LEVEL1 | BPF_LOG_LEVEL2) #define BPF_LOG_MASK (BPF_LOG_LEVEL | BPF_LOG_STATS) #define BPF_LOG_KERNEL (BPF_LOG_MASK + 1) /* kernel internal flag */ +#define BPF_LOG_MIN_ALIGNMENT 8 +#define BPF_LOG_ALIGNMENT_POS 32 static inline bool bpf_verifier_log_needed(const struct bpf_verifier_log *log) { @@ -481,6 +483,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; }; __printf(2, 0) void bpf_verifier_vlog(struct bpf_verifier_log *log, diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c index f4228864a3e9..a8f1426b0367 100644 --- a/kernel/bpf/verifier.c +++ b/kernel/bpf/verifier.c @@ -795,6 +795,27 @@ static void print_verifier_state(struct bpf_verifier_env *env, mark_verifier_state_clean(env); } +static u32 vlog_alignment(u32 prev_insn_print_len) +{ + if (prev_insn_print_len < BPF_LOG_ALIGNMENT_POS) + return BPF_LOG_ALIGNMENT_POS - prev_insn_print_len + 1; + return round_up(prev_insn_print_len, BPF_LOG_MIN_ALIGNMENT) - + prev_insn_print_len; +} + +static void print_prev_insn_state(struct bpf_verifier_env *env, + const struct bpf_func_state *state) +{ + if (env->prev_log_len == env->log.len_used) { + if (env->prev_log_len) + bpf_vlog_reset(&env->log, env->prev_log_len - 1); + verbose(env, "%*c;", vlog_alignment(env->prev_insn_print_len), + ' '); + } else + verbose(env, "%d:", env->insn_idx); + print_verifier_state(env, state); +} + /* copy array src of length n * size bytes to dst. dst is reallocated if it's too * small to hold src. This is different from krealloc since we don't want to preserve * the contents of dst. @@ -2723,10 +2744,11 @@ static int __mark_chain_precision(struct bpf_verifier_env *env, int regno, reg->precise = true; } if (env->log.level & BPF_LOG_LEVEL) { - print_verifier_state(env, func); - verbose(env, "parent %s regs=%x stack=%llx marks\n", + mark_verifier_state_scratched(env); + verbose(env, "parent %s regs=%x stack=%llx marks:", new_marks ? "didn't have" : "already had", reg_mask, stack_mask); + print_verifier_state(env, func); } if (!reg_mask && !stack_mask) @@ -3421,11 +3443,8 @@ static int check_mem_region_access(struct bpf_verifier_env *env, u32 regno, /* We may have adjusted the register pointing to memory region, so we * need to try adding each of min_value and max_value to off * to make sure our theoretical access will be safe. - */ - if (env->log.level & BPF_LOG_LEVEL) - print_verifier_state(env, state); - - /* The minimum value is only important with signed + * + * The minimum value is only important with signed * comparisons where we can't assume the floor of a * value is 0. If we are using signed variables for our * index'es we need to make sure that whatever we use @@ -4564,6 +4583,8 @@ static int check_mem_access(struct bpf_verifier_env *env, int insn_idx, u32 regn static int check_atomic(struct bpf_verifier_env *env, int insn_idx, struct bpf_insn *insn) { + struct bpf_verifier_state *vstate = env->cur_state; + struct bpf_func_state *state = vstate->frame[vstate->curframe]; int load_reg; int err; @@ -4650,6 +4671,9 @@ static int check_atomic(struct bpf_verifier_env *env, int insn_idx, struct bpf_i if (err) return err; + if (env->log.level & BPF_LOG_LEVEL) + print_prev_insn_state(env, state); + return 0; } @@ -9441,8 +9465,10 @@ static int check_cond_jmp_op(struct bpf_verifier_env *env, insn->dst_reg); return -EACCES; } - if (env->log.level & BPF_LOG_LEVEL) - print_verifier_state(env, this_branch->frame[this_branch->curframe]); + if (env->log.level & BPF_LOG_LEVEL) { + print_prev_insn_state( + env, this_branch->frame[this_branch->curframe]); + } return 0; } @@ -11310,17 +11336,12 @@ static int do_check(struct bpf_verifier_env *env) if (need_resched()) cond_resched(); - if ((env->log.level & BPF_LOG_LEVEL2) || - (env->log.level & BPF_LOG_LEVEL && do_print_state)) { - if (verifier_state_scratched(env) && - (env->log.level & BPF_LOG_LEVEL2)) - verbose(env, "%d:", env->insn_idx); - else - verbose(env, "\nfrom %d to %d%s:", - env->prev_insn_idx, env->insn_idx, - env->cur_state->speculative ? - " (speculative execution)" : ""); - print_verifier_state(env, state->frame[state->curframe]); + if (env->log.level & BPF_LOG_LEVEL1 && do_print_state) { + verbose(env, "\nfrom %d to %d%s:\n", env->prev_insn_idx, + env->insn_idx, + env->cur_state->speculative ? + " (speculative execution)" : + ""); do_print_state = false; } @@ -11331,9 +11352,17 @@ static int do_check(struct bpf_verifier_env *env) .private_data = env, }; + if (verifier_state_scratched(env)) + print_prev_insn_state( + env, state->frame[state->curframe]); + verbose_linfo(env, env->insn_idx, "; "); + env->prev_log_len = env->log.len_used; 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; } if (bpf_prog_is_dev_bound(env->prog->aux)) { diff --git a/tools/testing/selftests/bpf/prog_tests/align.c b/tools/testing/selftests/bpf/prog_tests/align.c index aeb2080a67f7..0a63cdfe0b5b 100644 --- a/tools/testing/selftests/bpf/prog_tests/align.c +++ b/tools/testing/selftests/bpf/prog_tests/align.c @@ -41,11 +41,11 @@ static struct bpf_align_test tests[] = { .matches = { {0, "R1=ctx(id=0,off=0,imm=0)"}, {0, "R10=fp0"}, - {1, "R3_w=inv2"}, - {2, "R3_w=inv4"}, - {3, "R3_w=inv8"}, - {4, "R3_w=inv16"}, - {5, "R3_w=inv32"}, + {0, "R3_w=inv2"}, + {1, "R3_w=inv4"}, + {2, "R3_w=inv8"}, + {3, "R3_w=inv16"}, + {4, "R3_w=inv32"}, }, }, { @@ -69,17 +69,17 @@ static struct bpf_align_test tests[] = { .matches = { {0, "R1=ctx(id=0,off=0,imm=0)"}, {0, "R10=fp0"}, - {1, "R3_w=inv1"}, - {2, "R3_w=inv2"}, - {3, "R3_w=inv4"}, - {4, "R3_w=inv8"}, - {5, "R3_w=inv16"}, - {6, "R3_w=inv1"}, - {7, "R4_w=inv32"}, - {8, "R4_w=inv16"}, - {9, "R4_w=inv8"}, - {10, "R4_w=inv4"}, - {11, "R4_w=inv2"}, + {0, "R3_w=inv1"}, + {1, "R3_w=inv2"}, + {2, "R3_w=inv4"}, + {3, "R3_w=inv8"}, + {4, "R3_w=inv16"}, + {5, "R3_w=inv1"}, + {6, "R4_w=inv32"}, + {7, "R4_w=inv16"}, + {8, "R4_w=inv8"}, + {9, "R4_w=inv4"}, + {10, "R4_w=inv2"}, }, }, { @@ -98,12 +98,12 @@ static struct bpf_align_test tests[] = { .matches = { {0, "R1=ctx(id=0,off=0,imm=0)"}, {0, "R10=fp0"}, - {1, "R3_w=inv4"}, - {2, "R3_w=inv8"}, - {3, "R3_w=inv10"}, - {4, "R4_w=inv8"}, - {5, "R4_w=inv12"}, - {6, "R4_w=inv14"}, + {0, "R3_w=inv4"}, + {1, "R3_w=inv8"}, + {2, "R3_w=inv10"}, + {3, "R4_w=inv8"}, + {4, "R4_w=inv12"}, + {5, "R4_w=inv14"}, }, }, { @@ -120,10 +120,10 @@ static struct bpf_align_test tests[] = { .matches = { {0, "R1=ctx(id=0,off=0,imm=0)"}, {0, "R10=fp0"}, + {0, "R3_w=inv7"}, {1, "R3_w=inv7"}, - {2, "R3_w=inv7"}, - {3, "R3_w=inv14"}, - {4, "R3_w=inv56"}, + {2, "R3_w=inv14"}, + {3, "R3_w=inv56"}, }, }, @@ -161,19 +161,19 @@ static struct bpf_align_test tests[] = { }, .prog_type = BPF_PROG_TYPE_SCHED_CLS, .matches = { - {6, "R0_w=pkt(id=0,off=8,r=8,imm=0)"}, - {7, "R3_w=inv(id=0,umax_value=255,var_off=(0x0; 0xff))"}, - {8, "R3_w=inv(id=0,umax_value=510,var_off=(0x0; 0x1fe))"}, - {9, "R3_w=inv(id=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, - {10, "R3_w=inv(id=0,umax_value=2040,var_off=(0x0; 0x7f8))"}, - {11, "R3_w=inv(id=0,umax_value=4080,var_off=(0x0; 0xff0))"}, - {13, "R3_w=pkt_end(id=0,off=0,imm=0)"}, - {18, "R4_w=inv(id=0,umax_value=255,var_off=(0x0; 0xff))"}, - {19, "R4_w=inv(id=0,umax_value=8160,var_off=(0x0; 0x1fe0))"}, - {20, "R4_w=inv(id=0,umax_value=4080,var_off=(0x0; 0xff0))"}, - {21, "R4_w=inv(id=0,umax_value=2040,var_off=(0x0; 0x7f8))"}, - {22, "R4_w=inv(id=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, - {23, "R4_w=inv(id=0,umax_value=510,var_off=(0x0; 0x1fe))"}, + {5, "R0_w=pkt(id=0,off=8,r=8,imm=0)"}, + {6, "R3_w=inv(id=0,umax_value=255,var_off=(0x0; 0xff))"}, + {7, "R3_w=inv(id=0,umax_value=510,var_off=(0x0; 0x1fe))"}, + {8, "R3_w=inv(id=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, + {9, "R3_w=inv(id=0,umax_value=2040,var_off=(0x0; 0x7f8))"}, + {10, "R3_w=inv(id=0,umax_value=4080,var_off=(0x0; 0xff0))"}, + {12, "R3_w=pkt_end(id=0,off=0,imm=0)"}, + {17, "R4_w=inv(id=0,umax_value=255,var_off=(0x0; 0xff))"}, + {18, "R4_w=inv(id=0,umax_value=8160,var_off=(0x0; 0x1fe0))"}, + {19, "R4_w=inv(id=0,umax_value=4080,var_off=(0x0; 0xff0))"}, + {20, "R4_w=inv(id=0,umax_value=2040,var_off=(0x0; 0x7f8))"}, + {21, "R4_w=inv(id=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, + {22, "R4_w=inv(id=0,umax_value=510,var_off=(0x0; 0x1fe))"}, }, }, { @@ -194,16 +194,16 @@ static struct bpf_align_test tests[] = { }, .prog_type = BPF_PROG_TYPE_SCHED_CLS, .matches = { - {7, "R3_w=inv(id=0,umax_value=255,var_off=(0x0; 0xff))"}, - {8, "R4_w=inv(id=1,umax_value=255,var_off=(0x0; 0xff))"}, - {9, "R4_w=inv(id=0,umax_value=255,var_off=(0x0; 0xff))"}, - {10, "R4_w=inv(id=1,umax_value=255,var_off=(0x0; 0xff))"}, - {11, "R4_w=inv(id=0,umax_value=510,var_off=(0x0; 0x1fe))"}, - {12, "R4_w=inv(id=1,umax_value=255,var_off=(0x0; 0xff))"}, - {13, "R4_w=inv(id=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, - {14, "R4_w=inv(id=1,umax_value=255,var_off=(0x0; 0xff))"}, - {15, "R4_w=inv(id=0,umax_value=2040,var_off=(0x0; 0x7f8))"}, - {16, "R4_w=inv(id=0,umax_value=4080,var_off=(0x0; 0xff0))"}, + {6, "R3_w=inv(id=0,umax_value=255,var_off=(0x0; 0xff))"}, + {7, "R4_w=inv(id=1,umax_value=255,var_off=(0x0; 0xff))"}, + {8, "R4_w=inv(id=0,umax_value=255,var_off=(0x0; 0xff))"}, + {9, "R4_w=inv(id=1,umax_value=255,var_off=(0x0; 0xff))"}, + {10, "R4_w=inv(id=0,umax_value=510,var_off=(0x0; 0x1fe))"}, + {11, "R4_w=inv(id=1,umax_value=255,var_off=(0x0; 0xff))"}, + {12, "R4_w=inv(id=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, + {13, "R4_w=inv(id=1,umax_value=255,var_off=(0x0; 0xff))"}, + {14, "R4_w=inv(id=0,umax_value=2040,var_off=(0x0; 0x7f8))"}, + {15, "R4_w=inv(id=0,umax_value=4080,var_off=(0x0; 0xff0))"}, }, }, { @@ -234,14 +234,14 @@ static struct bpf_align_test tests[] = { }, .prog_type = BPF_PROG_TYPE_SCHED_CLS, .matches = { - {3, "R5_w=pkt(id=0,off=0,r=0,imm=0)"}, - {5, "R5_w=pkt(id=0,off=14,r=0,imm=0)"}, - {6, "R4_w=pkt(id=0,off=14,r=0,imm=0)"}, - {9, "R2=pkt(id=0,off=0,r=18,imm=0)"}, + {2, "R5_w=pkt(id=0,off=0,r=0,imm=0)"}, + {4, "R5_w=pkt(id=0,off=14,r=0,imm=0)"}, + {5, "R4_w=pkt(id=0,off=14,r=0,imm=0)"}, + {8, "R2=pkt(id=0,off=0,r=18,imm=0)"}, {10, "R5=pkt(id=0,off=14,r=18,imm=0)"}, {10, "R4_w=inv(id=0,umax_value=255,var_off=(0x0; 0xff))"}, + {13, "R4_w=inv(id=0,umax_value=65535,var_off=(0x0; 0xffff))"}, {14, "R4_w=inv(id=0,umax_value=65535,var_off=(0x0; 0xffff))"}, - {15, "R4_w=inv(id=0,umax_value=65535,var_off=(0x0; 0xffff))"}, }, }, { @@ -297,7 +297,7 @@ static struct bpf_align_test tests[] = { * alignment of 4. */ {6, "R2_w=pkt(id=0,off=0,r=8,imm=0)"}, - {8, "R6_w=inv(id=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, + {7, "R6_w=inv(id=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, /* Offset is added to packet pointer R5, resulting in * known fixed offset, and variable offset from R6. */ @@ -308,47 +308,47 @@ static struct bpf_align_test tests[] = { * offset is considered using reg->aux_off_align which * is 4 and meets the load's requirements. */ - {15, "R4=pkt(id=1,off=18,r=18,umax_value=1020,var_off=(0x0; 0x3fc))"}, - {15, "R5=pkt(id=1,off=14,r=18,umax_value=1020,var_off=(0x0; 0x3fc))"}, + {14, "R4=pkt(id=1,off=18,r=18,umax_value=1020,var_off=(0x0; 0x3fc))"}, + {14, "R5=pkt(id=1,off=14,r=18,umax_value=1020,var_off=(0x0; 0x3fc))"}, /* Variable offset is added to R5 packet pointer, * resulting in auxiliary alignment of 4. */ - {18, "R5_w=pkt(id=2,off=0,r=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, + {17, "R5_w=pkt(id=2,off=0,r=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, /* Constant offset is added to R5, resulting in * reg->off of 14. */ - {19, "R5_w=pkt(id=2,off=14,r=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, + {18, "R5_w=pkt(id=2,off=14,r=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, /* At the time the word size load is performed from R5, * its total fixed offset is NET_IP_ALIGN + reg->off * (14) which is 16. Then the variable offset is 4-byte * aligned, so the total offset is 4-byte aligned and * meets the load's requirements. */ - {23, "R4=pkt(id=2,off=18,r=18,umax_value=1020,var_off=(0x0; 0x3fc))"}, - {23, "R5=pkt(id=2,off=14,r=18,umax_value=1020,var_off=(0x0; 0x3fc))"}, + {22, "R4=pkt(id=2,off=18,r=18,umax_value=1020,var_off=(0x0; 0x3fc))"}, + {22, "R5=pkt(id=2,off=14,r=18,umax_value=1020,var_off=(0x0; 0x3fc))"}, /* Constant offset is added to R5 packet pointer, * resulting in reg->off value of 14. */ - {26, "R5_w=pkt(id=0,off=14,r=8"}, + {25, "R5_w=pkt(id=0,off=14,r=8"}, /* Variable offset is added to R5, resulting in a * variable offset of (4n). */ - {27, "R5_w=pkt(id=3,off=14,r=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, + {26, "R5_w=pkt(id=3,off=14,r=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, /* Constant is added to R5 again, setting reg->off to 18. */ - {28, "R5_w=pkt(id=3,off=18,r=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, + {27, "R5_w=pkt(id=3,off=18,r=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, /* And once more we add a variable; resulting var_off * is still (4n), fixed offset is not changed. * Also, we create a new reg->id. */ - {29, "R5_w=pkt(id=4,off=18,r=0,umax_value=2040,var_off=(0x0; 0x7fc)"}, + {28, "R5_w=pkt(id=4,off=18,r=0,umax_value=2040,var_off=(0x0; 0x7fc)"}, /* At the time the word size load is performed from R5, * its total fixed offset is NET_IP_ALIGN + reg->off (18) * which is 20. Then the variable offset is (4n), so * the total offset is 4-byte aligned and meets the * load's requirements. */ - {33, "R4=pkt(id=4,off=22,r=22,umax_value=2040,var_off=(0x0; 0x7fc)"}, - {33, "R5=pkt(id=4,off=18,r=22,umax_value=2040,var_off=(0x0; 0x7fc)"}, + {32, "R4=pkt(id=4,off=22,r=22,umax_value=2040,var_off=(0x0; 0x7fc)"}, + {32, "R5=pkt(id=4,off=18,r=22,umax_value=2040,var_off=(0x0; 0x7fc)"}, }, }, { @@ -387,35 +387,35 @@ static struct bpf_align_test tests[] = { * alignment of 4. */ {6, "R2_w=pkt(id=0,off=0,r=8,imm=0)"}, - {8, "R6_w=inv(id=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, + {7, "R6_w=inv(id=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, /* Adding 14 makes R6 be (4n+2) */ - {9, "R6_w=inv(id=0,umin_value=14,umax_value=1034,var_off=(0x2; 0x7fc))"}, + {8, "R6_w=inv(id=0,umin_value=14,umax_value=1034,var_off=(0x2; 0x7fc))"}, /* Packet pointer has (4n+2) offset */ {11, "R5_w=pkt(id=1,off=0,r=0,umin_value=14,umax_value=1034,var_off=(0x2; 0x7fc)"}, - {13, "R4=pkt(id=1,off=4,r=0,umin_value=14,umax_value=1034,var_off=(0x2; 0x7fc)"}, + {12, "R4=pkt(id=1,off=4,r=0,umin_value=14,umax_value=1034,var_off=(0x2; 0x7fc)"}, /* At the time the word size load is performed from R5, * its total fixed offset is NET_IP_ALIGN + reg->off (0) * which is 2. Then the variable offset is (4n+2), so * the total offset is 4-byte aligned and meets the * load's requirements. */ - {15, "R5=pkt(id=1,off=0,r=4,umin_value=14,umax_value=1034,var_off=(0x2; 0x7fc)"}, + {14, "R5=pkt(id=1,off=0,r=4,umin_value=14,umax_value=1034,var_off=(0x2; 0x7fc)"}, /* Newly read value in R6 was shifted left by 2, so has * known alignment of 4. */ - {18, "R6_w=inv(id=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, + {17, "R6_w=inv(id=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, /* Added (4n) to packet pointer's (4n+2) var_off, giving * another (4n+2). */ {19, "R5_w=pkt(id=2,off=0,r=0,umin_value=14,umax_value=2054,var_off=(0x2; 0xffc)"}, - {21, "R4=pkt(id=2,off=4,r=0,umin_value=14,umax_value=2054,var_off=(0x2; 0xffc)"}, + {20, "R4=pkt(id=2,off=4,r=0,umin_value=14,umax_value=2054,var_off=(0x2; 0xffc)"}, /* At the time the word size load is performed from R5, * its total fixed offset is NET_IP_ALIGN + reg->off (0) * which is 2. Then the variable offset is (4n+2), so * the total offset is 4-byte aligned and meets the * load's requirements. */ - {23, "R5=pkt(id=2,off=0,r=4,umin_value=14,umax_value=2054,var_off=(0x2; 0xffc)"}, + {22, "R5=pkt(id=2,off=0,r=4,umin_value=14,umax_value=2054,var_off=(0x2; 0xffc)"}, }, }, { @@ -448,18 +448,18 @@ static struct bpf_align_test tests[] = { .prog_type = BPF_PROG_TYPE_SCHED_CLS, .result = REJECT, .matches = { - {4, "R5_w=pkt_end(id=0,off=0,imm=0)"}, + {3, "R5_w=pkt_end(id=0,off=0,imm=0)"}, /* (ptr - ptr) << 2 == unknown, (4n) */ - {6, "R5_w=inv(id=0,smax_value=9223372036854775804,umax_value=18446744073709551612,var_off=(0x0; 0xfffffffffffffffc)"}, + {5, "R5_w=inv(id=0,smax_value=9223372036854775804,umax_value=18446744073709551612,var_off=(0x0; 0xfffffffffffffffc)"}, /* (4n) + 14 == (4n+2). We blow our bounds, because * the add could overflow. */ - {7, "R5_w=inv(id=0,smin_value=-9223372036854775806,smax_value=9223372036854775806,umin_value=2,umax_value=18446744073709551614,var_off=(0x2; 0xfffffffffffffffc)"}, + {6, "R5_w=inv(id=0,smin_value=-9223372036854775806,smax_value=9223372036854775806,umin_value=2,umax_value=18446744073709551614,var_off=(0x2; 0xfffffffffffffffc)"}, /* Checked s>=0 */ - {9, "R5=inv(id=0,umin_value=2,umax_value=9223372036854775806,var_off=(0x2; 0x7ffffffffffffffc)"}, + {8, "R5=inv(id=0,umin_value=2,umax_value=9223372036854775806,var_off=(0x2; 0x7ffffffffffffffc)"}, /* packet pointer + nonnegative (4n+2) */ - {12, "R6_w=pkt(id=1,off=0,r=0,umin_value=2,umax_value=9223372036854775806,var_off=(0x2; 0x7ffffffffffffffc)"}, - {13, "R4_w=pkt(id=1,off=4,r=0,umin_value=2,umax_value=9223372036854775806,var_off=(0x2; 0x7ffffffffffffffc)"}, + {11, "R6_w=pkt(id=1,off=0,r=0,umin_value=2,umax_value=9223372036854775806,var_off=(0x2; 0x7ffffffffffffffc)"}, + {12, "R4_w=pkt(id=1,off=4,r=0,umin_value=2,umax_value=9223372036854775806,var_off=(0x2; 0x7ffffffffffffffc)"}, /* NET_IP_ALIGN + (4n+2) == (4n), alignment is fine. * We checked the bounds, but it might have been able * to overflow if the packet pointer started in the @@ -467,7 +467,7 @@ static struct bpf_align_test tests[] = { * So we did not get a 'range' on R6, and the access * attempt will fail. */ - {15, "R6_w=pkt(id=1,off=0,r=0,umin_value=2,umax_value=9223372036854775806,var_off=(0x2; 0x7ffffffffffffffc)"}, + {14, "R6_w=pkt(id=1,off=0,r=0,umin_value=2,umax_value=9223372036854775806,var_off=(0x2; 0x7ffffffffffffffc)"}, } }, { @@ -502,23 +502,23 @@ static struct bpf_align_test tests[] = { /* Calculated offset in R6 has unknown value, but known * alignment of 4. */ - {7, "R2_w=pkt(id=0,off=0,r=8,imm=0)"}, - {9, "R6_w=inv(id=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, + {6, "R2_w=pkt(id=0,off=0,r=8,imm=0)"}, + {8, "R6_w=inv(id=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, /* Adding 14 makes R6 be (4n+2) */ - {10, "R6_w=inv(id=0,umin_value=14,umax_value=1034,var_off=(0x2; 0x7fc))"}, + {9, "R6_w=inv(id=0,umin_value=14,umax_value=1034,var_off=(0x2; 0x7fc))"}, /* New unknown value in R7 is (4n) */ - {11, "R7_w=inv(id=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, + {10, "R7_w=inv(id=0,umax_value=1020,var_off=(0x0; 0x3fc))"}, /* Subtracting it from R6 blows our unsigned bounds */ - {12, "R6=inv(id=0,smin_value=-1006,smax_value=1034,umin_value=2,umax_value=18446744073709551614,var_off=(0x2; 0xfffffffffffffffc)"}, + {11, "R6=inv(id=0,smin_value=-1006,smax_value=1034,umin_value=2,umax_value=18446744073709551614,var_off=(0x2; 0xfffffffffffffffc)"}, /* Checked s>= 0 */ - {14, "R6=inv(id=0,umin_value=2,umax_value=1034,var_off=(0x2; 0x7fc))"}, + {13, "R6=inv(id=0,umin_value=2,umax_value=1034,var_off=(0x2; 0x7fc))"}, /* At the time the word size load is performed from R5, * its total fixed offset is NET_IP_ALIGN + reg->off (0) * which is 2. Then the variable offset is (4n+2), so * the total offset is 4-byte aligned and meets the * load's requirements. */ - {20, "R5=pkt(id=2,off=0,r=4,umin_value=2,umax_value=1034,var_off=(0x2; 0x7fc)"}, + {19, "R5=pkt(id=2,off=0,r=4,umin_value=2,umax_value=1034,var_off=(0x2; 0x7fc)"}, }, }, @@ -556,14 +556,14 @@ static struct bpf_align_test tests[] = { /* Calculated offset in R6 has unknown value, but known * alignment of 4. */ - {7, "R2_w=pkt(id=0,off=0,r=8,imm=0)"}, - {10, "R6_w=inv(id=0,umax_value=60,var_off=(0x0; 0x3c))"}, + {6, "R2_w=pkt(id=0,off=0,r=8,imm=0)"}, + {9, "R6_w=inv(id=0,umax_value=60,var_off=(0x0; 0x3c))"}, /* Adding 14 makes R6 be (4n+2) */ - {11, "R6_w=inv(id=0,umin_value=14,umax_value=74,var_off=(0x2; 0x7c))"}, + {10, "R6_w=inv(id=0,umin_value=14,umax_value=74,var_off=(0x2; 0x7c))"}, /* Subtracting from packet pointer overflows ubounds */ {13, "R5_w=pkt(id=2,off=0,r=8,umin_value=18446744073709551542,umax_value=18446744073709551602,var_off=(0xffffffffffffff82; 0x7c)"}, /* New unknown value in R7 is (4n), >= 76 */ - {15, "R7_w=inv(id=0,umin_value=76,umax_value=1096,var_off=(0x0; 0x7fc))"}, + {14, "R7_w=inv(id=0,umin_value=76,umax_value=1096,var_off=(0x0; 0x7fc))"}, /* Adding it to packet pointer gives nice bounds again */ {16, "R5_w=pkt(id=3,off=0,r=0,umin_value=2,umax_value=1082,var_off=(0x2; 0xfffffffc)"}, /* At the time the word size load is performed from R5, @@ -572,7 +572,7 @@ static struct bpf_align_test tests[] = { * the total offset is 4-byte aligned and meets the * load's requirements. */ - {20, "R5=pkt(id=3,off=0,r=4,umin_value=2,umax_value=1082,var_off=(0x2; 0xfffffffc)"}, + {19, "R5=pkt(id=3,off=0,r=4,umin_value=2,umax_value=1082,var_off=(0x2; 0xfffffffc)"}, }, }, }; @@ -642,7 +642,19 @@ static int do_test_single(struct bpf_align_test *test) printf("%s", bpf_vlog); break; } + /* Check the next line as well in case the previous line + * did not have a corresponding bpf insn. Example: + * func#0 @0 + * 0: R1=ctx(id=0,off=0,imm=0) R10=fp0 + * 0: (b7) r3 = 2 ; R3_w=inv2 + */ if (!strstr(line_ptr, m.match)) { + cur_line = -1; + line_ptr = strtok(NULL, "\n"); + sscanf(line_ptr, "%u: ", &cur_line); + } + if (cur_line != m.line || !line_ptr || + !strstr(line_ptr, m.match)) { printf("Failed to find match %u: %s\n", m.line, m.match); ret = 1; -- 2.30.2 ^ permalink raw reply related [flat|nested] 10+ messages in thread
* Re: [PATCH v2 bpf-next 2/3] Right align verifier states in verifier logs 2021-12-15 19:22 ` [PATCH v2 bpf-next 2/3] Right align verifier states in " Christy Lee @ 2021-12-16 7:02 ` Andrii Nakryiko [not found] ` <CAPqJDZr1AudE2PfbZQarHf0N5i_-xm-zyhfLqS5rogX98UtNLQ@mail.gmail.com> 0 siblings, 1 reply; 10+ messages in thread From: Andrii Nakryiko @ 2021-12-16 7:02 UTC (permalink / raw) To: Christy Lee Cc: Alexei Starovoitov, Daniel Borkmann, Andrii Nakryiko, bpf, Kernel Team, christyc.y.lee On Wed, Dec 15, 2021 at 11:22 AM Christy Lee <christylee@fb.com> wrote: > > Make the verifier logs more readable, print the verifier states > on the corresponding instruction line. If the previous line was > not a bpf instruction, then print the verifier states on its own > line. > > Before: > > Validating test_pkt_access_subprog3() func#3... > 86: R1=invP(id=0) R2=ctx(id=0,off=0,imm=0) R10=fp0 > ; int test_pkt_access_subprog3(int val, struct __sk_buff *skb) > 86: (bf) r6 = r2 > 87: R2=ctx(id=0,off=0,imm=0) R6_w=ctx(id=0,off=0,imm=0) > 87: (bc) w7 = w1 > 88: R1=invP(id=0) R7_w=invP(id=0,umax_value=4294967295,var_off=(0x0; 0xffffffff)) > ; return get_skb_len(skb) * get_skb_ifindex(val, skb, get_constant(123)); > 88: (bf) r1 = r6 > 89: R1_w=ctx(id=0,off=0,imm=0) R6_w=ctx(id=0,off=0,imm=0) > 89: (85) call pc+9 > Func#4 is global and valid. Skipping. > 90: R0_w=invP(id=0) > 90: (bc) w8 = w0 > 91: R0_w=invP(id=0) R8_w=invP(id=0,umax_value=4294967295,var_off=(0x0; 0xffffffff)) > ; return get_skb_len(skb) * get_skb_ifindex(val, skb, get_constant(123)); > 91: (b7) r1 = 123 > 92: R1_w=invP123 > 92: (85) call pc+65 > Func#5 is global and valid. Skipping. > 93: R0=invP(id=0) > > After: > > Validating test_pkt_access_subprog3() func#3... > 86: R1=invP(id=0) R2=ctx(id=0,off=0,imm=0) R10=fp0 > ; int test_pkt_access_subprog3(int val, struct __sk_buff *skb) > 86: (bf) r6 = r2 ; R2=ctx(id=0,off=0,imm=0) R6_w=ctx(id=0,off=0,imm=0) > 87: (bc) w7 = w1 ; R1=invP(id=0) R7_w=invP(id=0,umax_value=4294967295,var_off=(0x0; 0xffffffff)) > ; return get_skb_len(skb) * get_skb_ifindex(val, skb, get_constant(123)); > 88: (bf) r1 = r6 ; R1_w=ctx(id=0,off=0,imm=0) R6_w=ctx(id=0,off=0,imm=0) > 89: (85) call pc+9 > Func#4 is global and valid. Skipping. > 90: R0_w=invP(id=0) > 90: (bc) w8 = w0 ; R0_w=invP(id=0) R8_w=invP(id=0,umax_value=4294967295,var_off=(0x0; 0xffffffff)) > ; return get_skb_len(skb) * get_skb_ifindex(val, skb, get_constant(123)); > 91: (b7) r1 = 123 ; R1_w=invP123 > 92: (85) call pc+65 > Func#5 is global and valid. Skipping. > 93: R0=invP(id=0) There seems to be quite a lot of jumpin back and forth in terms of 33th (see off by one error below) vs 40th offsets (this is for pyperf50 test): 16: (07) r2 += -8 ; R2_w=fp-8 ; Event* event = bpf_map_lookup_elem(&eventmap, &zero); 17: (18) r1 = 0xffff88810d81dc00 ; R1_w=map_ptr(id=0,off=0,ks=4,vs=252,imm=0) 19: (85) call bpf_map_lookup_elem#1 ; R0=map_value_or_null(id=3,off=0,ks=4,vs=252,imm=0) 20: (bf) r7 = r0 ; R0=map_value_or_null(id=3,off=0,ks=4,vs=252,imm=0) R7_w=map_value_or_null(id=3,off=0,ks=4,vs=252,imm=0) ; if (!event) 21: (15) if r7 == 0x0 goto pc+5193 ; R7_w=map_value(id=0,off=0,ks=4,vs=252,imm=0) ; event->pid = pid; 22: (61) r1 = *(u32 *)(r10 -4) ; R1_w=inv(id=0,umax_value=4294967295,var_off=(0x0; 0xffffffff)) R10=fp0 Maybe let's bump the minimum to 40? > > Signed-off-by: Christy Lee <christylee@fb.com> > --- > include/linux/bpf_verifier.h | 3 + > kernel/bpf/verifier.c | 69 ++++-- > .../testing/selftests/bpf/prog_tests/align.c | 196 ++++++++++-------- > 3 files changed, 156 insertions(+), 112 deletions(-) > > diff --git a/include/linux/bpf_verifier.h b/include/linux/bpf_verifier.h > index c555222c97d6..cf5801c02216 100644 > --- a/include/linux/bpf_verifier.h > +++ b/include/linux/bpf_verifier.h > @@ -388,6 +388,8 @@ static inline bool bpf_verifier_log_full(const struct bpf_verifier_log *log) > #define BPF_LOG_LEVEL (BPF_LOG_LEVEL1 | BPF_LOG_LEVEL2) > #define BPF_LOG_MASK (BPF_LOG_LEVEL | BPF_LOG_STATS) > #define BPF_LOG_KERNEL (BPF_LOG_MASK + 1) /* kernel internal flag */ > +#define BPF_LOG_MIN_ALIGNMENT 8 > +#define BPF_LOG_ALIGNMENT_POS 32 > > static inline bool bpf_verifier_log_needed(const struct bpf_verifier_log *log) > { > @@ -481,6 +483,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; > }; > > __printf(2, 0) void bpf_verifier_vlog(struct bpf_verifier_log *log, > diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c > index f4228864a3e9..a8f1426b0367 100644 > --- a/kernel/bpf/verifier.c > +++ b/kernel/bpf/verifier.c > @@ -795,6 +795,27 @@ static void print_verifier_state(struct bpf_verifier_env *env, > mark_verifier_state_clean(env); > } > > +static u32 vlog_alignment(u32 prev_insn_print_len) > +{ > + if (prev_insn_print_len < BPF_LOG_ALIGNMENT_POS) > + return BPF_LOG_ALIGNMENT_POS - prev_insn_print_len + 1; why +1 here? > + return round_up(prev_insn_print_len, BPF_LOG_MIN_ALIGNMENT) - > + prev_insn_print_len; > +} > + > +static void print_prev_insn_state(struct bpf_verifier_env *env, > + const struct bpf_func_state *state) > +{ > + if (env->prev_log_len == env->log.len_used) { > + if (env->prev_log_len) > + bpf_vlog_reset(&env->log, env->prev_log_len - 1); I don't get this... why do we need this reset? Why just appending alignment spaces below doesn't work? > + verbose(env, "%*c;", vlog_alignment(env->prev_insn_print_len), > + ' '); nit: keep it on single line > + } else > + verbose(env, "%d:", env->insn_idx); if one branch of if/else has {}, the other one has to have them as well, even if it's a single line statement > + print_verifier_state(env, state); > +} > + > /* copy array src of length n * size bytes to dst. dst is reallocated if it's too > * small to hold src. This is different from krealloc since we don't want to preserve > * the contents of dst. [...] > @@ -9441,8 +9465,10 @@ static int check_cond_jmp_op(struct bpf_verifier_env *env, > insn->dst_reg); > return -EACCES; > } > - if (env->log.level & BPF_LOG_LEVEL) > - print_verifier_state(env, this_branch->frame[this_branch->curframe]); > + if (env->log.level & BPF_LOG_LEVEL) { > + print_prev_insn_state( > + env, this_branch->frame[this_branch->curframe]); nit: keep on a single line. But also is it really a "previous instruction" or still a current instruction? Maybe just "print_insn_state"? Do we have "next_insn" helper anywhere? If not, dropping this "prev_" prefix from helpers and variables would be cleaner, IMO > + } > return 0; > } > > @@ -11310,17 +11336,12 @@ static int do_check(struct bpf_verifier_env *env) > if (need_resched()) > cond_resched(); > > - if ((env->log.level & BPF_LOG_LEVEL2) || > - (env->log.level & BPF_LOG_LEVEL && do_print_state)) { > - if (verifier_state_scratched(env) && > - (env->log.level & BPF_LOG_LEVEL2)) > - verbose(env, "%d:", env->insn_idx); > - else > - verbose(env, "\nfrom %d to %d%s:", > - env->prev_insn_idx, env->insn_idx, > - env->cur_state->speculative ? > - " (speculative execution)" : ""); > - print_verifier_state(env, state->frame[state->curframe]); > + if (env->log.level & BPF_LOG_LEVEL1 && do_print_state) { () around bit operations > + verbose(env, "\nfrom %d to %d%s:\n", env->prev_insn_idx, > + env->insn_idx, > + env->cur_state->speculative ? > + " (speculative execution)" : > + ""); it's ok to go up to 100 characters, please keep the code more readable > do_print_state = false; > } > > @@ -11331,9 +11352,17 @@ static int do_check(struct bpf_verifier_env *env) > .private_data = env, > }; > > + if (verifier_state_scratched(env)) > + print_prev_insn_state( > + env, state->frame[state->curframe]); > + > verbose_linfo(env, env->insn_idx, "; "); > + env->prev_log_len = env->log.len_used; > 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; > } > > if (bpf_prog_is_dev_bound(env->prog->aux)) { [...] ^ permalink raw reply [flat|nested] 10+ messages in thread
[parent not found: <CAPqJDZr1AudE2PfbZQarHf0N5i_-xm-zyhfLqS5rogX98UtNLQ@mail.gmail.com>]
* Re: [PATCH v2 bpf-next 2/3] Right align verifier states in verifier logs [not found] ` <CAPqJDZr1AudE2PfbZQarHf0N5i_-xm-zyhfLqS5rogX98UtNLQ@mail.gmail.com> @ 2021-12-16 16:03 ` Christy Lee 2021-12-16 19:37 ` Andrii Nakryiko 0 siblings, 1 reply; 10+ messages in thread From: Christy Lee @ 2021-12-16 16:03 UTC (permalink / raw) To: Andrii Nakryiko Cc: Christy Lee, Alexei Starovoitov, Daniel Borkmann, Andrii Nakryiko, bpf, Kernel Team On Thu, Dec 16, 2021 at 7:59 AM Christy Lee <christyc.y.lee@gmail.com> wrote:> Apologies, resending this because the previous email was not plain text. > > On Wed, Dec 15, 2021 at 11:02 PM Andrii Nakryiko <andrii.nakryiko@gmail.com> wrote: >> >> On Wed, Dec 15, 2021 at 11:22 AM Christy Lee <christylee@fb.com> wrote: >> > > > [...] >> >> >> There seems to be quite a lot of jumpin back and forth in terms of >> 33th (see off by one error below) vs 40th offsets (this is for >> pyperf50 test): >> >> 16: (07) r2 += -8 ; R2_w=fp-8 >> ; Event* event = bpf_map_lookup_elem(&eventmap, &zero); >> 17: (18) r1 = 0xffff88810d81dc00 ; >> R1_w=map_ptr(id=0,off=0,ks=4,vs=252,imm=0) >> 19: (85) call bpf_map_lookup_elem#1 ; >> R0=map_value_or_null(id=3,off=0,ks=4,vs=252,imm=0) >> 20: (bf) r7 = r0 ; >> R0=map_value_or_null(id=3,off=0,ks=4,vs=252,imm=0) >> R7_w=map_value_or_null(id=3,off=0,ks=4,vs=252,imm=0) >> ; if (!event) >> 21: (15) if r7 == 0x0 goto pc+5193 ; >> R7_w=map_value(id=0,off=0,ks=4,vs=252,imm=0) >> ; event->pid = pid; >> 22: (61) r1 = *(u32 *)(r10 -4) ; >> R1_w=inv(id=0,umax_value=4294967295,var_off=(0x0; 0xffffffff)) R10=fp0 >> >> Maybe let's bump the minimum to 40? > > Will do! I'll experiment with the nicest looking offset. >> >> >> > >> > Signed-off-by: Christy Lee <christylee@fb.com> > > [...] >> >> > >> > +static u32 vlog_alignment(u32 prev_insn_print_len) >> > +{ >> > + if (prev_insn_print_len < BPF_LOG_ALIGNMENT_POS) >> > + return BPF_LOG_ALIGNMENT_POS - prev_insn_print_len + 1; >> >> why +1 here? > > I wanted the insn_state to be prepended by BPF_LOG_ALIGNMENT_POS > number of characters, in this case, that would be prepended by 32 and starting > at 33. This ensures that whether prev_insn_print_len is smaller than > BPF_LOG_ALIGNMENT_POS or not, the insn_states would be aligned properly, > there would be an off-by-one error otherwise. >> >> >> > + return round_up(prev_insn_print_len, BPF_LOG_MIN_ALIGNMENT) - >> > + prev_insn_print_len; >> > +} >> > + >> > +static void print_prev_insn_state(struct bpf_verifier_env *env, >> > + const struct bpf_func_state *state) >> > +{ >> > + if (env->prev_log_len == env->log.len_used) { >> > + if (env->prev_log_len) >> > + bpf_vlog_reset(&env->log, env->prev_log_len - 1); >> >> I don't get this... why do we need this reset? Why just appending >> alignment spaces below doesn't work? > > The insn are printed via print_bpf_insn() which ends the line with a '\n', we need to > reset one character in order to remove the new line and print insn_state on the same > line. print_bpf_insn() is defined in kernel/bpf/disasm.h and used by bpf_tool as well, so I > didn't want to modify it. >> >> >> > + verbose(env, "%*c;", vlog_alignment(env->prev_insn_print_len), >> > + ' '); >> >> nit: keep it on single line >> >> > + } else >> > + verbose(env, "%d:", env->insn_idx); >> >> if one branch of if/else has {}, the other one has to have them as >> well, even if it's a single line statement >> >> > + print_verifier_state(env, state); >> > +} >> > + >> > /* copy array src of length n * size bytes to dst. dst is reallocated if it's too >> > * small to hold src. This is different from krealloc since we don't want to preserve >> > * the contents of dst. >> >> [...] >> >> > @@ -9441,8 +9465,10 @@ static int check_cond_jmp_op(struct bpf_verifier_env *env, >> > insn->dst_reg); >> > return -EACCES; >> > } >> > - if (env->log.level & BPF_LOG_LEVEL) >> > - print_verifier_state(env, this_branch->frame[this_branch->curframe]); >> > + if (env->log.level & BPF_LOG_LEVEL) { >> > + print_prev_insn_state( >> > + env, this_branch->frame[this_branch->curframe]); >> >> nit: keep on a single line. But also is it really a "previous >> instruction" or still a current instruction? Maybe just >> "print_insn_state"? Do we have "next_insn" helper anywhere? If not, >> dropping this "prev_" prefix from helpers and variables would be >> cleaner, IMO >> >> > + } >> > return 0; >> > } >> > >> > @@ -11310,17 +11336,12 @@ static int do_check(struct bpf_verifier_env *env) >> > if (need_resched()) >> > cond_resched(); >> > >> > - if ((env->log.level & BPF_LOG_LEVEL2) || >> > - (env->log.level & BPF_LOG_LEVEL && do_print_state)) { >> > - if (verifier_state_scratched(env) && >> > - (env->log.level & BPF_LOG_LEVEL2)) >> > - verbose(env, "%d:", env->insn_idx); >> > - else >> > - verbose(env, "\nfrom %d to %d%s:", >> > - env->prev_insn_idx, env->insn_idx, >> > - env->cur_state->speculative ? >> > - " (speculative execution)" : ""); >> > - print_verifier_state(env, state->frame[state->curframe]); >> > + if (env->log.level & BPF_LOG_LEVEL1 && do_print_state) { >> >> () around bit operations >> >> > + verbose(env, "\nfrom %d to %d%s:\n", env->prev_insn_idx, >> > + env->insn_idx, >> > + env->cur_state->speculative ? >> > + " (speculative execution)" : >> > + ""); >> >> it's ok to go up to 100 characters, please keep the code more readable >> >> > do_print_state = false; >> > } >> > >> > @@ -11331,9 +11352,17 @@ static int do_check(struct bpf_verifier_env *env) >> > .private_data = env, >> > }; >> > >> > + if (verifier_state_scratched(env)) >> > + print_prev_insn_state( >> > + env, state->frame[state->curframe]); >> > + >> > verbose_linfo(env, env->insn_idx, "; "); >> > + env->prev_log_len = env->log.len_used; >> > 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; >> > } >> > >> > if (bpf_prog_is_dev_bound(env->prog->aux)) { >> >> [...] ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH v2 bpf-next 2/3] Right align verifier states in verifier logs 2021-12-16 16:03 ` Christy Lee @ 2021-12-16 19:37 ` Andrii Nakryiko 0 siblings, 0 replies; 10+ messages in thread From: Andrii Nakryiko @ 2021-12-16 19:37 UTC (permalink / raw) To: Christy Lee Cc: Christy Lee, Alexei Starovoitov, Daniel Borkmann, Andrii Nakryiko, bpf, Kernel Team On Thu, Dec 16, 2021 at 8:03 AM Christy Lee <christyc.y.lee@gmail.com> wrote: > > On Thu, Dec 16, 2021 at 7:59 AM Christy Lee <christyc.y.lee@gmail.com> wrote:> > > Apologies, resending this because the previous email was not plain text. > > > > > On Wed, Dec 15, 2021 at 11:02 PM Andrii Nakryiko <andrii.nakryiko@gmail.com> wrote: > >> > >> On Wed, Dec 15, 2021 at 11:22 AM Christy Lee <christylee@fb.com> wrote: > >> > > > > > [...] > >> > >> > >> There seems to be quite a lot of jumpin back and forth in terms of > >> 33th (see off by one error below) vs 40th offsets (this is for > >> pyperf50 test): > >> > >> 16: (07) r2 += -8 ; R2_w=fp-8 > >> ; Event* event = bpf_map_lookup_elem(&eventmap, &zero); > >> 17: (18) r1 = 0xffff88810d81dc00 ; > >> R1_w=map_ptr(id=0,off=0,ks=4,vs=252,imm=0) > >> 19: (85) call bpf_map_lookup_elem#1 ; > >> R0=map_value_or_null(id=3,off=0,ks=4,vs=252,imm=0) > >> 20: (bf) r7 = r0 ; > >> R0=map_value_or_null(id=3,off=0,ks=4,vs=252,imm=0) > >> R7_w=map_value_or_null(id=3,off=0,ks=4,vs=252,imm=0) > >> ; if (!event) > >> 21: (15) if r7 == 0x0 goto pc+5193 ; > >> R7_w=map_value(id=0,off=0,ks=4,vs=252,imm=0) > >> ; event->pid = pid; > >> 22: (61) r1 = *(u32 *)(r10 -4) ; > >> R1_w=inv(id=0,umax_value=4294967295,var_off=(0x0; 0xffffffff)) R10=fp0 > >> > >> Maybe let's bump the minimum to 40? > > > > Will do! I'll experiment with the nicest looking offset. > >> > >> > >> > > >> > Signed-off-by: Christy Lee <christylee@fb.com> > > > > [...] > >> > >> > > >> > +static u32 vlog_alignment(u32 prev_insn_print_len) > >> > +{ > >> > + if (prev_insn_print_len < BPF_LOG_ALIGNMENT_POS) > >> > + return BPF_LOG_ALIGNMENT_POS - prev_insn_print_len + 1; > >> > >> why +1 here? > > > > I wanted the insn_state to be prepended by BPF_LOG_ALIGNMENT_POS > > number of characters, in this case, that would be prepended by 32 and starting > > at 33. This ensures that whether prev_insn_print_len is smaller than > > BPF_LOG_ALIGNMENT_POS or not, the insn_states would be aligned properly, > > there would be an off-by-one error otherwise. > >> > >> > >> > + return round_up(prev_insn_print_len, BPF_LOG_MIN_ALIGNMENT) - > >> > + prev_insn_print_len; > >> > +} > >> > + > >> > +static void print_prev_insn_state(struct bpf_verifier_env *env, > >> > + const struct bpf_func_state *state) > >> > +{ > >> > + if (env->prev_log_len == env->log.len_used) { > >> > + if (env->prev_log_len) > >> > + bpf_vlog_reset(&env->log, env->prev_log_len - 1); > >> > >> I don't get this... why do we need this reset? Why just appending > >> alignment spaces below doesn't work? > > > > The insn are printed via print_bpf_insn() which ends the line with a '\n', we need to > > reset one character in order to remove the new line and print insn_state on the same > > line. print_bpf_insn() is defined in kernel/bpf/disasm.h and used by bpf_tool as well, so I > > didn't want to modify it. oh, can you please leave a small comment explaining that? > >> > >> > >> > + verbose(env, "%*c;", vlog_alignment(env->prev_insn_print_len), > >> > + ' '); > >> > >> nit: keep it on single line > >> > >> > + } else > >> > + verbose(env, "%d:", env->insn_idx); > >> > >> if one branch of if/else has {}, the other one has to have them as > >> well, even if it's a single line statement > >> > >> > + print_verifier_state(env, state); > >> > +} > >> > + > >> > /* copy array src of length n * size bytes to dst. dst is reallocated if it's too > >> > * small to hold src. This is different from krealloc since we don't want to preserve > >> > * the contents of dst. > >> > >> [...] > >> > >> > @@ -9441,8 +9465,10 @@ static int check_cond_jmp_op(struct bpf_verifier_env *env, > >> > insn->dst_reg); > >> > return -EACCES; > >> > } > >> > - if (env->log.level & BPF_LOG_LEVEL) > >> > - print_verifier_state(env, this_branch->frame[this_branch->curframe]); > >> > + if (env->log.level & BPF_LOG_LEVEL) { > >> > + print_prev_insn_state( > >> > + env, this_branch->frame[this_branch->curframe]); > >> > >> nit: keep on a single line. But also is it really a "previous > >> instruction" or still a current instruction? Maybe just > >> "print_insn_state"? Do we have "next_insn" helper anywhere? If not, > >> dropping this "prev_" prefix from helpers and variables would be > >> cleaner, IMO > >> > >> > + } > >> > return 0; > >> > } > >> > > >> > @@ -11310,17 +11336,12 @@ static int do_check(struct bpf_verifier_env *env) > >> > if (need_resched()) > >> > cond_resched(); > >> > > >> > - if ((env->log.level & BPF_LOG_LEVEL2) || > >> > - (env->log.level & BPF_LOG_LEVEL && do_print_state)) { > >> > - if (verifier_state_scratched(env) && > >> > - (env->log.level & BPF_LOG_LEVEL2)) > >> > - verbose(env, "%d:", env->insn_idx); > >> > - else > >> > - verbose(env, "\nfrom %d to %d%s:", > >> > - env->prev_insn_idx, env->insn_idx, > >> > - env->cur_state->speculative ? > >> > - " (speculative execution)" : ""); > >> > - print_verifier_state(env, state->frame[state->curframe]); > >> > + if (env->log.level & BPF_LOG_LEVEL1 && do_print_state) { > >> > >> () around bit operations > >> > >> > + verbose(env, "\nfrom %d to %d%s:\n", env->prev_insn_idx, > >> > + env->insn_idx, > >> > + env->cur_state->speculative ? > >> > + " (speculative execution)" : > >> > + ""); > >> > >> it's ok to go up to 100 characters, please keep the code more readable > >> > >> > do_print_state = false; > >> > } > >> > > >> > @@ -11331,9 +11352,17 @@ static int do_check(struct bpf_verifier_env *env) > >> > .private_data = env, > >> > }; > >> > > >> > + if (verifier_state_scratched(env)) > >> > + print_prev_insn_state( > >> > + env, state->frame[state->curframe]); > >> > + > >> > verbose_linfo(env, env->insn_idx, "; "); > >> > + env->prev_log_len = env->log.len_used; > >> > 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; > >> > } > >> > > >> > if (bpf_prog_is_dev_bound(env->prog->aux)) { > >> > >> [...] ^ permalink raw reply [flat|nested] 10+ messages in thread
* [PATCH v2 bpf-next 3/3] Only output backtracking information in log level 2 2021-12-15 19:22 [PATCH v2 bpf-next 0/3] Improve verifier log readability Christy Lee 2021-12-15 19:22 ` [PATCH v2 bpf-next 1/3] Only print scratched registers and stack slots to verifier logs Christy Lee 2021-12-15 19:22 ` [PATCH v2 bpf-next 2/3] Right align verifier states in " Christy Lee @ 2021-12-15 19:22 ` Christy Lee 2021-12-16 7:02 ` Andrii Nakryiko 2 siblings, 1 reply; 10+ messages in thread From: Christy Lee @ 2021-12-15 19:22 UTC (permalink / raw) To: ast, daniel, andrii; +Cc: bpf, kernel-team, christylee, christyc.y.lee Backtracking information is very verbose, don't print it in log level 1 to improve readability. Signed-off-by: Christy Lee <christylee@fb.com> --- kernel/bpf/verifier.c | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c index a8f1426b0367..2cb86972ed35 100644 --- a/kernel/bpf/verifier.c +++ b/kernel/bpf/verifier.c @@ -2398,7 +2398,7 @@ static int backtrack_insn(struct bpf_verifier_env *env, int idx, if (insn->code == 0) return 0; - if (env->log.level & BPF_LOG_LEVEL) { + if (env->log.level & BPF_LOG_LEVEL2) { verbose(env, "regs=%x stack=%llx before ", *reg_mask, *stack_mask); verbose(env, "%d: ", idx); print_bpf_insn(&cbs, insn, env->allow_ptr_leaks); @@ -2656,7 +2656,7 @@ static int __mark_chain_precision(struct bpf_verifier_env *env, int regno, DECLARE_BITMAP(mask, 64); u32 history = st->jmp_history_cnt; - if (env->log.level & BPF_LOG_LEVEL) + if (env->log.level & BPF_LOG_LEVEL2) verbose(env, "last_idx %d first_idx %d\n", last_idx, first_idx); for (i = last_idx;;) { if (skip_first) { @@ -2743,7 +2743,7 @@ static int __mark_chain_precision(struct bpf_verifier_env *env, int regno, new_marks = true; reg->precise = true; } - if (env->log.level & BPF_LOG_LEVEL) { + if (env->log.level & BPF_LOG_LEVEL2) { mark_verifier_state_scratched(env); verbose(env, "parent %s regs=%x stack=%llx marks:", new_marks ? "didn't have" : "already had", -- 2.30.2 ^ permalink raw reply related [flat|nested] 10+ messages in thread
* Re: [PATCH v2 bpf-next 3/3] Only output backtracking information in log level 2 2021-12-15 19:22 ` [PATCH v2 bpf-next 3/3] Only output backtracking information in log level 2 Christy Lee @ 2021-12-16 7:02 ` Andrii Nakryiko 0 siblings, 0 replies; 10+ messages in thread From: Andrii Nakryiko @ 2021-12-16 7:02 UTC (permalink / raw) To: Christy Lee Cc: Alexei Starovoitov, Daniel Borkmann, Andrii Nakryiko, bpf, Kernel Team, christyc.y.lee On Wed, Dec 15, 2021 at 11:22 AM Christy Lee <christylee@fb.com> wrote: > > Backtracking information is very verbose, don't print it in log > level 1 to improve readability. > > Signed-off-by: Christy Lee <christylee@fb.com> > --- LGTM. Acked-by: Andrii Nakryiko <andrii@kernel.org> > kernel/bpf/verifier.c | 6 +++--- > 1 file changed, 3 insertions(+), 3 deletions(-) > > diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c > index a8f1426b0367..2cb86972ed35 100644 > --- a/kernel/bpf/verifier.c > +++ b/kernel/bpf/verifier.c > @@ -2398,7 +2398,7 @@ static int backtrack_insn(struct bpf_verifier_env *env, int idx, > > if (insn->code == 0) > return 0; > - if (env->log.level & BPF_LOG_LEVEL) { > + if (env->log.level & BPF_LOG_LEVEL2) { > verbose(env, "regs=%x stack=%llx before ", *reg_mask, *stack_mask); > verbose(env, "%d: ", idx); > print_bpf_insn(&cbs, insn, env->allow_ptr_leaks); > @@ -2656,7 +2656,7 @@ static int __mark_chain_precision(struct bpf_verifier_env *env, int regno, > DECLARE_BITMAP(mask, 64); > u32 history = st->jmp_history_cnt; > > - if (env->log.level & BPF_LOG_LEVEL) > + if (env->log.level & BPF_LOG_LEVEL2) > verbose(env, "last_idx %d first_idx %d\n", last_idx, first_idx); > for (i = last_idx;;) { > if (skip_first) { > @@ -2743,7 +2743,7 @@ static int __mark_chain_precision(struct bpf_verifier_env *env, int regno, > new_marks = true; > reg->precise = true; > } > - if (env->log.level & BPF_LOG_LEVEL) { > + if (env->log.level & BPF_LOG_LEVEL2) { > mark_verifier_state_scratched(env); > verbose(env, "parent %s regs=%x stack=%llx marks:", > new_marks ? "didn't have" : "already had", > -- > 2.30.2 > ^ permalink raw reply [flat|nested] 10+ messages in thread
end of thread, other threads:[~2021-12-16 19:37 UTC | newest]
Thread overview: 10+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-12-15 19:22 [PATCH v2 bpf-next 0/3] Improve verifier log readability Christy Lee
2021-12-15 19:22 ` [PATCH v2 bpf-next 1/3] Only print scratched registers and stack slots to verifier logs Christy Lee
2021-12-16 7:02 ` Andrii Nakryiko
[not found] ` <CAPqJDZpuZ586TawooQhxZGvOqgF4yCjT0yOLEXAUer8eJDO7gw@mail.gmail.com>
2021-12-16 16:02 ` Christy Lee
2021-12-15 19:22 ` [PATCH v2 bpf-next 2/3] Right align verifier states in " Christy Lee
2021-12-16 7:02 ` Andrii Nakryiko
[not found] ` <CAPqJDZr1AudE2PfbZQarHf0N5i_-xm-zyhfLqS5rogX98UtNLQ@mail.gmail.com>
2021-12-16 16:03 ` Christy Lee
2021-12-16 19:37 ` Andrii Nakryiko
2021-12-15 19:22 ` [PATCH v2 bpf-next 3/3] Only output backtracking information in log level 2 Christy Lee
2021-12-16 7:02 ` Andrii Nakryiko
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).