On Mon, Dec 13, 2021 at 10:21 AM Christy Lee <christylee@xxxxxx> 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)
This is a huge improvement, makes the log so much more useful. But if
it's not available in log_level = 1 most people will never get to
enjoy the benefits. I think we should absolutely do this for all
log_levels. It might increase the size of the log for log_level in
terms of number of bytes emitted into the log, but the clarity of
what's going on is totally worth it.
But I'm also confused why it's not available with log_level = 2 for
successfully verified programs. Do you have any idea. Running sudo
./test_progs -t log_buf -v, I get this for "GOOD_PROG" case (which
uses log_level 2):
=================
GOOD_PROG LOG:
=================
func#0 @0
arg#0 reference type('UNKNOWN ') size cannot be determined: -22
0: R1=ctx(id=0,off=0,imm=0) R10=fp0
; a[0] = (int)(long)ctx;
0: (18) r2 = 0xffffc90000572000
2: R2_w=map_value(id=0,off=0,ks=4,vs=16,imm=0)
2: (63) *(u32 *)(r2 +0) = r1
R1=ctx(id=0,off=0,imm=0) R2_w=map_value(id=0,off=0,ks=4,vs=16,imm=0)
from 2 to 3:
; return a[1];
3: (61) r0 = *(u32 *)(r2 +4)
R2_w=map_value(id=0,off=0,ks=4,vs=16,imm=0)
from 3 to 4:
; return a[1];
4: (95) exit
processed 4 insns (limit 1000000) max_states_per_insn 0 total_states 0
peak_states 0 mark_read 0
No right alignment :( What am I missing?
Also, your changes broke lots of test_progs, please see [0] and fix
them. Thanks.
[0] https://github.com/kernel-patches/bpf/runs/4513474703?check_suite_focus=true
>
> Signed-off-by: Christy Lee <christylee@xxxxxx>
> ---
> include/linux/bpf_verifier.h | 2 +
> kernel/bpf/verifier.c | 26 ++-
> .../testing/selftests/bpf/prog_tests/align.c | 196 ++++++++++--------
> 3 files changed, 131 insertions(+), 93 deletions(-)
>
[...]
