On Tue, Dec 14, 2021 at 9:07 AM Christy Lee-Eusman (PL&R)
<christylee@xxxxxx> wrote:
>
>
>
> > On Dec 13, 2021, at 5:12 PM, Andrii Nakryiko <andrii.nakryiko@xxxxxxxxx> wrote:
> >
> > 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)
>
> 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.
That sounds like some bug in verifier's logging? Can you please see if
you can fix that as part of your patch set then?
>
> > 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!
great, thanks
> >
> >>
> >> 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(-)
> >>
> >
> > [...]
>
