Re: [PATCH bpf-next 2/3] Right align verifier states in verifier logs

["Christy Lee-Eusman (PL&R)" <christylee@fb.com>]

> On Dec 13, 2021, at 5:12 PM, Andrii Nakryiko <andrii.nakryiko@gmail.com> wrote:
> 
> On Mon, Dec 13, 2021 at 10:21 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)
> 
> 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)

For correctness reasons, when we print verifier state, I check that the current
instruction index is previous instruction Index + 1. In this case, the logs skipped
Printing out instruction index 1, so the state at 2 is not aligned to instruction 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)

In this case the verifier state is printed “out-of-band” from instruction index, so I
didn't align it. Now that I think about it though, I can do an additional check to
see if the line printed before the verifier state is an instruction line and align it
correspondingly.

> 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

Thanks for pointing it out! Looks like the latest rebase broke this, I’ll fix this right away!
> 
>> 
>> Signed-off-by: Christy Lee <christylee@fb.com>
>> ---
>> 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(-)
>> 
> 
> [...]