Hitting verifier backtracking bug on 6.5.5 kernel

Hitting verifier backtracking bug on 6.5.5 kernel

[Toke Høiland-Jørgensen]

Hi Andrii

Mohamed ran into what appears to be a verifier bug related to your
commit:

fde2a3882bd0 ("bpf: support precision propagation in the presence of subprogs")

So I figured you'd be the person to ask about this :)

The issue appears on a vanilla 6.5 kernel (on both 6.5.6 on Fedora 38,
and 6.5.5 on my Arch machine):

INFO[0000] Verifier error: load program: bad address:
	1861: frame2: R1_w=fp-160 R2_w=pkt_end(off=0,imm=0) R3=scalar(umin=17,umax=255,var_off=(0x0; 0xff)) R4_w=fp-96 R6_w=fp-96 R7_w=pkt(off=34,r=34,imm=0) R10=fp0
	; switch (protocol) {
	1861: (15) if r3 == 0x11 goto pc+22 1884: frame2: R1_w=fp-160 R2_w=pkt_end(off=0,imm=0) R3=17 R4_w=fp-96 R6_w=fp-96 R7_w=pkt(off=34,r=34,imm=0) R10=fp0
	; if ((void *)udp + sizeof(*udp) <= data_end) {
	1884: (bf) r3 = r7                    ; frame2: R3_w=pkt(off=34,r=34,imm=0) R7_w=pkt(off=34,r=34,imm=0)
	1885: (07) r3 += 8                    ; frame2: R3_w=pkt(off=42,r=34,imm=0)
	; if ((void *)udp + sizeof(*udp) <= data_end) {
	1886: (2d) if r3 > r2 goto pc+23      ; frame2: R2_w=pkt_end(off=0,imm=0) R3_w=pkt(off=42,r=42,imm=0)
	; id->src_port = bpf_ntohs(udp->source);
	1887: (69) r2 = *(u16 *)(r7 +0)       ; frame2: R2_w=scalar(umax=65535,var_off=(0x0; 0xffff)) R7_w=pkt(off=34,r=42,imm=0)
	1888: (bf) r3 = r2                    ; frame2: R2_w=scalar(id=103,umax=65535,var_off=(0x0; 0xffff)) R3_w=scalar(id=103,umax=65535,var_off=(0x0; 0xffff))
	1889: (dc) r3 = be16 r3               ; frame2: R3_w=scalar()
	; id->src_port = bpf_ntohs(udp->source);
	1890: (73) *(u8 *)(r1 +47) = r3       ; frame2: R1_w=fp-160 R3_w=scalar()
	; id->src_port = bpf_ntohs(udp->source);
	1891: (dc) r2 = be64 r2               ; frame2: R2_w=scalar()
	; id->src_port = bpf_ntohs(udp->source);
	1892: (77) r2 >>= 56                  ; frame2: R2_w=scalar(umax=255,var_off=(0x0; 0xff))
	1893: (73) *(u8 *)(r1 +48) = r2
	BUG regs 1
	processed 5121 insns (limit 1000000) max_states_per_insn 4 total_states 92 peak_states 90 mark_read 20
	(truncated)  component=ebpf.FlowFetcher

Dmesg says:

[252431.093126] verifier backtracking bug
[252431.093129] WARNING: CPU: 3 PID: 302245 at kernel/bpf/verifier.c:3533 __mark_chain_precision+0xe83/0x1090


The splat appears when trying to run the netobserv-ebpf-agent. Steps to
reproduce:

git clone https://github.com/netobserv/netobserv-ebpf-agent
cd netobserv-ebpf-agent && make compile
sudo FLOWS_TARGET_HOST=127.0.0.1 FLOWS_TARGET_PORT=9999 ./bin/netobserv-ebpf-agent

(It needs a 'make generate' before the compile to recompile the BPF
program itself, but that requires the Cilium bpf2go program to be
installed and there's a binary version checked into the tree so that is
not strictly necessary to reproduce the splat).

That project uses the Cilium Go eBPF loader. Interestingly, loading the
same program using tc (with libbpf 1.2.2) works just fine:

ip link add type veth
tc qdisc add dev veth0 clsact
tc filter add dev veth0 egress bpf direct-action obj pkg/ebpf/bpf_bpfel.o sec tc_egress

So maybe there is some massaging of the object file that libbpf is doing
but the Go library isn't, that prevents this bug from triggering? I'm
only guessing here, I don't really know exactly what the Go library is
doing under the hood.

Anyway, I guess this is a kernel bug in any case since that WARN() is
there; could you please take a look?

Thanks!

-Toke

Re: Hitting verifier backtracking bug on 6.5.5 kernel

[Andrii Nakryiko]

On Thu, Oct 12, 2023 at 1:25 PM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
>
> Hi Andrii
>
> Mohamed ran into what appears to be a verifier bug related to your
> commit:
>
> fde2a3882bd0 ("bpf: support precision propagation in the presence of subprogs")
>
> So I figured you'd be the person to ask about this :)
>
> The issue appears on a vanilla 6.5 kernel (on both 6.5.6 on Fedora 38,
> and 6.5.5 on my Arch machine):
>
> INFO[0000] Verifier error: load program: bad address:
>         1861: frame2: R1_w=fp-160 R2_w=pkt_end(off=0,imm=0) R3=scalar(umin=17,umax=255,var_off=(0x0; 0xff)) R4_w=fp-96 R6_w=fp-96 R7_w=pkt(off=34,r=34,imm=0) R10=fp0
>         ; switch (protocol) {
>         1861: (15) if r3 == 0x11 goto pc+22 1884: frame2: R1_w=fp-160 R2_w=pkt_end(off=0,imm=0) R3=17 R4_w=fp-96 R6_w=fp-96 R7_w=pkt(off=34,r=34,imm=0) R10=fp0
>         ; if ((void *)udp + sizeof(*udp) <= data_end) {
>         1884: (bf) r3 = r7                    ; frame2: R3_w=pkt(off=34,r=34,imm=0) R7_w=pkt(off=34,r=34,imm=0)
>         1885: (07) r3 += 8                    ; frame2: R3_w=pkt(off=42,r=34,imm=0)
>         ; if ((void *)udp + sizeof(*udp) <= data_end) {
>         1886: (2d) if r3 > r2 goto pc+23      ; frame2: R2_w=pkt_end(off=0,imm=0) R3_w=pkt(off=42,r=42,imm=0)
>         ; id->src_port = bpf_ntohs(udp->source);
>         1887: (69) r2 = *(u16 *)(r7 +0)       ; frame2: R2_w=scalar(umax=65535,var_off=(0x0; 0xffff)) R7_w=pkt(off=34,r=42,imm=0)
>         1888: (bf) r3 = r2                    ; frame2: R2_w=scalar(id=103,umax=65535,var_off=(0x0; 0xffff)) R3_w=scalar(id=103,umax=65535,var_off=(0x0; 0xffff))
>         1889: (dc) r3 = be16 r3               ; frame2: R3_w=scalar()
>         ; id->src_port = bpf_ntohs(udp->source);
>         1890: (73) *(u8 *)(r1 +47) = r3       ; frame2: R1_w=fp-160 R3_w=scalar()
>         ; id->src_port = bpf_ntohs(udp->source);
>         1891: (dc) r2 = be64 r2               ; frame2: R2_w=scalar()
>         ; id->src_port = bpf_ntohs(udp->source);
>         1892: (77) r2 >>= 56                  ; frame2: R2_w=scalar(umax=255,var_off=(0x0; 0xff))
>         1893: (73) *(u8 *)(r1 +48) = r2
>         BUG regs 1
>         processed 5121 insns (limit 1000000) max_states_per_insn 4 total_states 92 peak_states 90 mark_read 20
>         (truncated)  component=ebpf.FlowFetcher
>
> Dmesg says:
>
> [252431.093126] verifier backtracking bug
> [252431.093129] WARNING: CPU: 3 PID: 302245 at kernel/bpf/verifier.c:3533 __mark_chain_precision+0xe83/0x1090
>
>
> The splat appears when trying to run the netobserv-ebpf-agent. Steps to
> reproduce:
>
> git clone https://github.com/netobserv/netobserv-ebpf-agent
> cd netobserv-ebpf-agent && make compile
> sudo FLOWS_TARGET_HOST=127.0.0.1 FLOWS_TARGET_PORT=9999 ./bin/netobserv-ebpf-agent
>
> (It needs a 'make generate' before the compile to recompile the BPF
> program itself, but that requires the Cilium bpf2go program to be
> installed and there's a binary version checked into the tree so that is
> not strictly necessary to reproduce the splat).
>
> That project uses the Cilium Go eBPF loader. Interestingly, loading the
> same program using tc (with libbpf 1.2.2) works just fine:
>
> ip link add type veth
> tc qdisc add dev veth0 clsact
> tc filter add dev veth0 egress bpf direct-action obj pkg/ebpf/bpf_bpfel.o sec tc_egress
>
> So maybe there is some massaging of the object file that libbpf is doing
> but the Go library isn't, that prevents this bug from triggering? I'm
> only guessing here, I don't really know exactly what the Go library is
> doing under the hood.
>
> Anyway, I guess this is a kernel bug in any case since that WARN() is
> there; could you please take a look?
>

Yes, I tried. Unfortunately I can't build netobserv-ebpf-agent on my
dev machine and can't run it. I tried to load bpf_bpfel.o through
veristat, but unfortunately it is not libbpf-compatible.

Is there some way to get a full verifier log for the failure above?
with log_level 2, if possible? If you can share it through Github Gist
or something like that, I'd really appreciate it. Thanks!

> Thanks!
>
> -Toke
>

Re: Hitting verifier backtracking bug on 6.5.5 kernel

[Toke Høiland-Jørgensen]

Andrii Nakryiko <andrii.nakryiko@gmail.com> writes:

> On Thu, Oct 12, 2023 at 1:25 PM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
>>
>> Hi Andrii
>>
>> Mohamed ran into what appears to be a verifier bug related to your
>> commit:
>>
>> fde2a3882bd0 ("bpf: support precision propagation in the presence of subprogs")
>>
>> So I figured you'd be the person to ask about this :)
>>
>> The issue appears on a vanilla 6.5 kernel (on both 6.5.6 on Fedora 38,
>> and 6.5.5 on my Arch machine):
>>
>> INFO[0000] Verifier error: load program: bad address:
>>         1861: frame2: R1_w=fp-160 R2_w=pkt_end(off=0,imm=0) R3=scalar(umin=17,umax=255,var_off=(0x0; 0xff)) R4_w=fp-96 R6_w=fp-96 R7_w=pkt(off=34,r=34,imm=0) R10=fp0
>>         ; switch (protocol) {
>>         1861: (15) if r3 == 0x11 goto pc+22 1884: frame2: R1_w=fp-160 R2_w=pkt_end(off=0,imm=0) R3=17 R4_w=fp-96 R6_w=fp-96 R7_w=pkt(off=34,r=34,imm=0) R10=fp0
>>         ; if ((void *)udp + sizeof(*udp) <= data_end) {
>>         1884: (bf) r3 = r7                    ; frame2: R3_w=pkt(off=34,r=34,imm=0) R7_w=pkt(off=34,r=34,imm=0)
>>         1885: (07) r3 += 8                    ; frame2: R3_w=pkt(off=42,r=34,imm=0)
>>         ; if ((void *)udp + sizeof(*udp) <= data_end) {
>>         1886: (2d) if r3 > r2 goto pc+23      ; frame2: R2_w=pkt_end(off=0,imm=0) R3_w=pkt(off=42,r=42,imm=0)
>>         ; id->src_port = bpf_ntohs(udp->source);
>>         1887: (69) r2 = *(u16 *)(r7 +0)       ; frame2: R2_w=scalar(umax=65535,var_off=(0x0; 0xffff)) R7_w=pkt(off=34,r=42,imm=0)
>>         1888: (bf) r3 = r2                    ; frame2: R2_w=scalar(id=103,umax=65535,var_off=(0x0; 0xffff)) R3_w=scalar(id=103,umax=65535,var_off=(0x0; 0xffff))
>>         1889: (dc) r3 = be16 r3               ; frame2: R3_w=scalar()
>>         ; id->src_port = bpf_ntohs(udp->source);
>>         1890: (73) *(u8 *)(r1 +47) = r3       ; frame2: R1_w=fp-160 R3_w=scalar()
>>         ; id->src_port = bpf_ntohs(udp->source);
>>         1891: (dc) r2 = be64 r2               ; frame2: R2_w=scalar()
>>         ; id->src_port = bpf_ntohs(udp->source);
>>         1892: (77) r2 >>= 56                  ; frame2: R2_w=scalar(umax=255,var_off=(0x0; 0xff))
>>         1893: (73) *(u8 *)(r1 +48) = r2
>>         BUG regs 1
>>         processed 5121 insns (limit 1000000) max_states_per_insn 4 total_states 92 peak_states 90 mark_read 20
>>         (truncated)  component=ebpf.FlowFetcher
>>
>> Dmesg says:
>>
>> [252431.093126] verifier backtracking bug
>> [252431.093129] WARNING: CPU: 3 PID: 302245 at kernel/bpf/verifier.c:3533 __mark_chain_precision+0xe83/0x1090
>>
>>
>> The splat appears when trying to run the netobserv-ebpf-agent. Steps to
>> reproduce:
>>
>> git clone https://github.com/netobserv/netobserv-ebpf-agent
>> cd netobserv-ebpf-agent && make compile
>> sudo FLOWS_TARGET_HOST=127.0.0.1 FLOWS_TARGET_PORT=9999 ./bin/netobserv-ebpf-agent
>>
>> (It needs a 'make generate' before the compile to recompile the BPF
>> program itself, but that requires the Cilium bpf2go program to be
>> installed and there's a binary version checked into the tree so that is
>> not strictly necessary to reproduce the splat).
>>
>> That project uses the Cilium Go eBPF loader. Interestingly, loading the
>> same program using tc (with libbpf 1.2.2) works just fine:
>>
>> ip link add type veth
>> tc qdisc add dev veth0 clsact
>> tc filter add dev veth0 egress bpf direct-action obj pkg/ebpf/bpf_bpfel.o sec tc_egress
>>
>> So maybe there is some massaging of the object file that libbpf is doing
>> but the Go library isn't, that prevents this bug from triggering? I'm
>> only guessing here, I don't really know exactly what the Go library is
>> doing under the hood.
>>
>> Anyway, I guess this is a kernel bug in any case since that WARN() is
>> there; could you please take a look?
>>
>
> Yes, I tried. Unfortunately I can't build netobserv-ebpf-agent on my
> dev machine and can't run it. I tried to load bpf_bpfel.o through
> veristat, but unfortunately it is not libbpf-compatible.
>
> Is there some way to get a full verifier log for the failure above?
> with log_level 2, if possible? If you can share it through Github Gist
> or something like that, I'd really appreciate it. Thanks!

Sure, here you go:
https://gist.github.com/tohojo/31173d2bb07262a21393f76d9a45132d

-Toke

Re: Hitting verifier backtracking bug on 6.5.5 kernel

[Andrii Nakryiko]

On Mon, Oct 16, 2023 at 12:37 PM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
>
> Andrii Nakryiko <andrii.nakryiko@gmail.com> writes:
>
> > On Thu, Oct 12, 2023 at 1:25 PM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
> >>
> >> Hi Andrii
> >>
> >> Mohamed ran into what appears to be a verifier bug related to your
> >> commit:
> >>
> >> fde2a3882bd0 ("bpf: support precision propagation in the presence of subprogs")
> >>
> >> So I figured you'd be the person to ask about this :)
> >>
> >> The issue appears on a vanilla 6.5 kernel (on both 6.5.6 on Fedora 38,
> >> and 6.5.5 on my Arch machine):
> >>
> >> INFO[0000] Verifier error: load program: bad address:
> >>         1861: frame2: R1_w=fp-160 R2_w=pkt_end(off=0,imm=0) R3=scalar(umin=17,umax=255,var_off=(0x0; 0xff)) R4_w=fp-96 R6_w=fp-96 R7_w=pkt(off=34,r=34,imm=0) R10=fp0
> >>         ; switch (protocol) {
> >>         1861: (15) if r3 == 0x11 goto pc+22 1884: frame2: R1_w=fp-160 R2_w=pkt_end(off=0,imm=0) R3=17 R4_w=fp-96 R6_w=fp-96 R7_w=pkt(off=34,r=34,imm=0) R10=fp0
> >>         ; if ((void *)udp + sizeof(*udp) <= data_end) {
> >>         1884: (bf) r3 = r7                    ; frame2: R3_w=pkt(off=34,r=34,imm=0) R7_w=pkt(off=34,r=34,imm=0)
> >>         1885: (07) r3 += 8                    ; frame2: R3_w=pkt(off=42,r=34,imm=0)
> >>         ; if ((void *)udp + sizeof(*udp) <= data_end) {
> >>         1886: (2d) if r3 > r2 goto pc+23      ; frame2: R2_w=pkt_end(off=0,imm=0) R3_w=pkt(off=42,r=42,imm=0)
> >>         ; id->src_port = bpf_ntohs(udp->source);
> >>         1887: (69) r2 = *(u16 *)(r7 +0)       ; frame2: R2_w=scalar(umax=65535,var_off=(0x0; 0xffff)) R7_w=pkt(off=34,r=42,imm=0)
> >>         1888: (bf) r3 = r2                    ; frame2: R2_w=scalar(id=103,umax=65535,var_off=(0x0; 0xffff)) R3_w=scalar(id=103,umax=65535,var_off=(0x0; 0xffff))
> >>         1889: (dc) r3 = be16 r3               ; frame2: R3_w=scalar()
> >>         ; id->src_port = bpf_ntohs(udp->source);
> >>         1890: (73) *(u8 *)(r1 +47) = r3       ; frame2: R1_w=fp-160 R3_w=scalar()
> >>         ; id->src_port = bpf_ntohs(udp->source);
> >>         1891: (dc) r2 = be64 r2               ; frame2: R2_w=scalar()
> >>         ; id->src_port = bpf_ntohs(udp->source);
> >>         1892: (77) r2 >>= 56                  ; frame2: R2_w=scalar(umax=255,var_off=(0x0; 0xff))
> >>         1893: (73) *(u8 *)(r1 +48) = r2
> >>         BUG regs 1
> >>         processed 5121 insns (limit 1000000) max_states_per_insn 4 total_states 92 peak_states 90 mark_read 20
> >>         (truncated)  component=ebpf.FlowFetcher
> >>
> >> Dmesg says:
> >>
> >> [252431.093126] verifier backtracking bug
> >> [252431.093129] WARNING: CPU: 3 PID: 302245 at kernel/bpf/verifier.c:3533 __mark_chain_precision+0xe83/0x1090
> >>
> >>
> >> The splat appears when trying to run the netobserv-ebpf-agent. Steps to
> >> reproduce:
> >>
> >> git clone https://github.com/netobserv/netobserv-ebpf-agent
> >> cd netobserv-ebpf-agent && make compile
> >> sudo FLOWS_TARGET_HOST=127.0.0.1 FLOWS_TARGET_PORT=9999 ./bin/netobserv-ebpf-agent
> >>
> >> (It needs a 'make generate' before the compile to recompile the BPF
> >> program itself, but that requires the Cilium bpf2go program to be
> >> installed and there's a binary version checked into the tree so that is
> >> not strictly necessary to reproduce the splat).
> >>
> >> That project uses the Cilium Go eBPF loader. Interestingly, loading the
> >> same program using tc (with libbpf 1.2.2) works just fine:
> >>
> >> ip link add type veth
> >> tc qdisc add dev veth0 clsact
> >> tc filter add dev veth0 egress bpf direct-action obj pkg/ebpf/bpf_bpfel.o sec tc_egress
> >>
> >> So maybe there is some massaging of the object file that libbpf is doing
> >> but the Go library isn't, that prevents this bug from triggering? I'm
> >> only guessing here, I don't really know exactly what the Go library is
> >> doing under the hood.
> >>
> >> Anyway, I guess this is a kernel bug in any case since that WARN() is
> >> there; could you please take a look?
> >>
> >
> > Yes, I tried. Unfortunately I can't build netobserv-ebpf-agent on my
> > dev machine and can't run it. I tried to load bpf_bpfel.o through
> > veristat, but unfortunately it is not libbpf-compatible.
> >
> > Is there some way to get a full verifier log for the failure above?
> > with log_level 2, if possible? If you can share it through Github Gist
> > or something like that, I'd really appreciate it. Thanks!
>
> Sure, here you go:
> https://gist.github.com/tohojo/31173d2bb07262a21393f76d9a45132d

Thanks, this is very useful. And it's pretty clear what happens from
last few lines:

    mark_precise: frame2: regs=r2 stack= before 1890: (dc) r2 = be64 r2
    mark_precise: frame2: regs=r0,r2 stack= before 1889: (73) *(u8
*)(r1 +47) = r3

See how we add r0 to the regs set, while there is no r0 involved in
`r2 = be64 r2`? I think it's just a missing case of handling BPF_END
(and perhaps BPF_NEG as well) instructions in backtrack_insn(). Should
be a trivial fix, though ideally we should also add some test for this
as well.

>
> -Toke
>

Re: Hitting verifier backtracking bug on 6.5.5 kernel

[Toke Høiland-Jørgensen]

Andrii Nakryiko <andrii.nakryiko@gmail.com> writes:

> On Mon, Oct 16, 2023 at 12:37 PM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
>>
>> Andrii Nakryiko <andrii.nakryiko@gmail.com> writes:
>>
>> > On Thu, Oct 12, 2023 at 1:25 PM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
>> >>
>> >> Hi Andrii
>> >>
>> >> Mohamed ran into what appears to be a verifier bug related to your
>> >> commit:
>> >>
>> >> fde2a3882bd0 ("bpf: support precision propagation in the presence of subprogs")
>> >>
>> >> So I figured you'd be the person to ask about this :)
>> >>
>> >> The issue appears on a vanilla 6.5 kernel (on both 6.5.6 on Fedora 38,
>> >> and 6.5.5 on my Arch machine):
>> >>
>> >> INFO[0000] Verifier error: load program: bad address:
>> >>         1861: frame2: R1_w=fp-160 R2_w=pkt_end(off=0,imm=0) R3=scalar(umin=17,umax=255,var_off=(0x0; 0xff)) R4_w=fp-96 R6_w=fp-96 R7_w=pkt(off=34,r=34,imm=0) R10=fp0
>> >>         ; switch (protocol) {
>> >>         1861: (15) if r3 == 0x11 goto pc+22 1884: frame2: R1_w=fp-160 R2_w=pkt_end(off=0,imm=0) R3=17 R4_w=fp-96 R6_w=fp-96 R7_w=pkt(off=34,r=34,imm=0) R10=fp0
>> >>         ; if ((void *)udp + sizeof(*udp) <= data_end) {
>> >>         1884: (bf) r3 = r7                    ; frame2: R3_w=pkt(off=34,r=34,imm=0) R7_w=pkt(off=34,r=34,imm=0)
>> >>         1885: (07) r3 += 8                    ; frame2: R3_w=pkt(off=42,r=34,imm=0)
>> >>         ; if ((void *)udp + sizeof(*udp) <= data_end) {
>> >>         1886: (2d) if r3 > r2 goto pc+23      ; frame2: R2_w=pkt_end(off=0,imm=0) R3_w=pkt(off=42,r=42,imm=0)
>> >>         ; id->src_port = bpf_ntohs(udp->source);
>> >>         1887: (69) r2 = *(u16 *)(r7 +0)       ; frame2: R2_w=scalar(umax=65535,var_off=(0x0; 0xffff)) R7_w=pkt(off=34,r=42,imm=0)
>> >>         1888: (bf) r3 = r2                    ; frame2: R2_w=scalar(id=103,umax=65535,var_off=(0x0; 0xffff)) R3_w=scalar(id=103,umax=65535,var_off=(0x0; 0xffff))
>> >>         1889: (dc) r3 = be16 r3               ; frame2: R3_w=scalar()
>> >>         ; id->src_port = bpf_ntohs(udp->source);
>> >>         1890: (73) *(u8 *)(r1 +47) = r3       ; frame2: R1_w=fp-160 R3_w=scalar()
>> >>         ; id->src_port = bpf_ntohs(udp->source);
>> >>         1891: (dc) r2 = be64 r2               ; frame2: R2_w=scalar()
>> >>         ; id->src_port = bpf_ntohs(udp->source);
>> >>         1892: (77) r2 >>= 56                  ; frame2: R2_w=scalar(umax=255,var_off=(0x0; 0xff))
>> >>         1893: (73) *(u8 *)(r1 +48) = r2
>> >>         BUG regs 1
>> >>         processed 5121 insns (limit 1000000) max_states_per_insn 4 total_states 92 peak_states 90 mark_read 20
>> >>         (truncated)  component=ebpf.FlowFetcher
>> >>
>> >> Dmesg says:
>> >>
>> >> [252431.093126] verifier backtracking bug
>> >> [252431.093129] WARNING: CPU: 3 PID: 302245 at kernel/bpf/verifier.c:3533 __mark_chain_precision+0xe83/0x1090
>> >>
>> >>
>> >> The splat appears when trying to run the netobserv-ebpf-agent. Steps to
>> >> reproduce:
>> >>
>> >> git clone https://github.com/netobserv/netobserv-ebpf-agent
>> >> cd netobserv-ebpf-agent && make compile
>> >> sudo FLOWS_TARGET_HOST=127.0.0.1 FLOWS_TARGET_PORT=9999 ./bin/netobserv-ebpf-agent
>> >>
>> >> (It needs a 'make generate' before the compile to recompile the BPF
>> >> program itself, but that requires the Cilium bpf2go program to be
>> >> installed and there's a binary version checked into the tree so that is
>> >> not strictly necessary to reproduce the splat).
>> >>
>> >> That project uses the Cilium Go eBPF loader. Interestingly, loading the
>> >> same program using tc (with libbpf 1.2.2) works just fine:
>> >>
>> >> ip link add type veth
>> >> tc qdisc add dev veth0 clsact
>> >> tc filter add dev veth0 egress bpf direct-action obj pkg/ebpf/bpf_bpfel.o sec tc_egress
>> >>
>> >> So maybe there is some massaging of the object file that libbpf is doing
>> >> but the Go library isn't, that prevents this bug from triggering? I'm
>> >> only guessing here, I don't really know exactly what the Go library is
>> >> doing under the hood.
>> >>
>> >> Anyway, I guess this is a kernel bug in any case since that WARN() is
>> >> there; could you please take a look?
>> >>
>> >
>> > Yes, I tried. Unfortunately I can't build netobserv-ebpf-agent on my
>> > dev machine and can't run it. I tried to load bpf_bpfel.o through
>> > veristat, but unfortunately it is not libbpf-compatible.
>> >
>> > Is there some way to get a full verifier log for the failure above?
>> > with log_level 2, if possible? If you can share it through Github Gist
>> > or something like that, I'd really appreciate it. Thanks!
>>
>> Sure, here you go:
>> https://gist.github.com/tohojo/31173d2bb07262a21393f76d9a45132d
>
> Thanks, this is very useful. And it's pretty clear what happens from
> last few lines:
>
>     mark_precise: frame2: regs=r2 stack= before 1890: (dc) r2 = be64 r2
>     mark_precise: frame2: regs=r0,r2 stack= before 1889: (73) *(u8
> *)(r1 +47) = r3
>
> See how we add r0 to the regs set, while there is no r0 involved in
> `r2 = be64 r2`? I think it's just a missing case of handling BPF_END
> (and perhaps BPF_NEG as well) instructions in backtrack_insn(). Should
> be a trivial fix, though ideally we should also add some test for this
> as well.

Sounds good, thank you for looking into it! Let me know if you need me
to test a patch :)

-Toke

Re: Hitting verifier backtracking bug on 6.5.5 kernel

[Mohamed Mahmoud]

Any idea why the same verification errors are not seen when the
program is attached with bpftool ?

Thanks!
Mohamed


On Tue, Oct 17, 2023 at 7:08 AM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
>
> Andrii Nakryiko <andrii.nakryiko@gmail.com> writes:
>
> > On Mon, Oct 16, 2023 at 12:37 PM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
> >>
> >> Andrii Nakryiko <andrii.nakryiko@gmail.com> writes:
> >>
> >> > On Thu, Oct 12, 2023 at 1:25 PM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
> >> >>
> >> >> Hi Andrii
> >> >>
> >> >> Mohamed ran into what appears to be a verifier bug related to your
> >> >> commit:
> >> >>
> >> >> fde2a3882bd0 ("bpf: support precision propagation in the presence of subprogs")
> >> >>
> >> >> So I figured you'd be the person to ask about this :)
> >> >>
> >> >> The issue appears on a vanilla 6.5 kernel (on both 6.5.6 on Fedora 38,
> >> >> and 6.5.5 on my Arch machine):
> >> >>
> >> >> INFO[0000] Verifier error: load program: bad address:
> >> >>         1861: frame2: R1_w=fp-160 R2_w=pkt_end(off=0,imm=0) R3=scalar(umin=17,umax=255,var_off=(0x0; 0xff)) R4_w=fp-96 R6_w=fp-96 R7_w=pkt(off=34,r=34,imm=0) R10=fp0
> >> >>         ; switch (protocol) {
> >> >>         1861: (15) if r3 == 0x11 goto pc+22 1884: frame2: R1_w=fp-160 R2_w=pkt_end(off=0,imm=0) R3=17 R4_w=fp-96 R6_w=fp-96 R7_w=pkt(off=34,r=34,imm=0) R10=fp0
> >> >>         ; if ((void *)udp + sizeof(*udp) <= data_end) {
> >> >>         1884: (bf) r3 = r7                    ; frame2: R3_w=pkt(off=34,r=34,imm=0) R7_w=pkt(off=34,r=34,imm=0)
> >> >>         1885: (07) r3 += 8                    ; frame2: R3_w=pkt(off=42,r=34,imm=0)
> >> >>         ; if ((void *)udp + sizeof(*udp) <= data_end) {
> >> >>         1886: (2d) if r3 > r2 goto pc+23      ; frame2: R2_w=pkt_end(off=0,imm=0) R3_w=pkt(off=42,r=42,imm=0)
> >> >>         ; id->src_port = bpf_ntohs(udp->source);
> >> >>         1887: (69) r2 = *(u16 *)(r7 +0)       ; frame2: R2_w=scalar(umax=65535,var_off=(0x0; 0xffff)) R7_w=pkt(off=34,r=42,imm=0)
> >> >>         1888: (bf) r3 = r2                    ; frame2: R2_w=scalar(id=103,umax=65535,var_off=(0x0; 0xffff)) R3_w=scalar(id=103,umax=65535,var_off=(0x0; 0xffff))
> >> >>         1889: (dc) r3 = be16 r3               ; frame2: R3_w=scalar()
> >> >>         ; id->src_port = bpf_ntohs(udp->source);
> >> >>         1890: (73) *(u8 *)(r1 +47) = r3       ; frame2: R1_w=fp-160 R3_w=scalar()
> >> >>         ; id->src_port = bpf_ntohs(udp->source);
> >> >>         1891: (dc) r2 = be64 r2               ; frame2: R2_w=scalar()
> >> >>         ; id->src_port = bpf_ntohs(udp->source);
> >> >>         1892: (77) r2 >>= 56                  ; frame2: R2_w=scalar(umax=255,var_off=(0x0; 0xff))
> >> >>         1893: (73) *(u8 *)(r1 +48) = r2
> >> >>         BUG regs 1
> >> >>         processed 5121 insns (limit 1000000) max_states_per_insn 4 total_states 92 peak_states 90 mark_read 20
> >> >>         (truncated)  component=ebpf.FlowFetcher
> >> >>
> >> >> Dmesg says:
> >> >>
> >> >> [252431.093126] verifier backtracking bug
> >> >> [252431.093129] WARNING: CPU: 3 PID: 302245 at kernel/bpf/verifier.c:3533 __mark_chain_precision+0xe83/0x1090
> >> >>
> >> >>
> >> >> The splat appears when trying to run the netobserv-ebpf-agent. Steps to
> >> >> reproduce:
> >> >>
> >> >> git clone https://github.com/netobserv/netobserv-ebpf-agent
> >> >> cd netobserv-ebpf-agent && make compile
> >> >> sudo FLOWS_TARGET_HOST=127.0.0.1 FLOWS_TARGET_PORT=9999 ./bin/netobserv-ebpf-agent
> >> >>
> >> >> (It needs a 'make generate' before the compile to recompile the BPF
> >> >> program itself, but that requires the Cilium bpf2go program to be
> >> >> installed and there's a binary version checked into the tree so that is
> >> >> not strictly necessary to reproduce the splat).
> >> >>
> >> >> That project uses the Cilium Go eBPF loader. Interestingly, loading the
> >> >> same program using tc (with libbpf 1.2.2) works just fine:
> >> >>
> >> >> ip link add type veth
> >> >> tc qdisc add dev veth0 clsact
> >> >> tc filter add dev veth0 egress bpf direct-action obj pkg/ebpf/bpf_bpfel.o sec tc_egress
> >> >>
> >> >> So maybe there is some massaging of the object file that libbpf is doing
> >> >> but the Go library isn't, that prevents this bug from triggering? I'm
> >> >> only guessing here, I don't really know exactly what the Go library is
> >> >> doing under the hood.
> >> >>
> >> >> Anyway, I guess this is a kernel bug in any case since that WARN() is
> >> >> there; could you please take a look?
> >> >>
> >> >
> >> > Yes, I tried. Unfortunately I can't build netobserv-ebpf-agent on my
> >> > dev machine and can't run it. I tried to load bpf_bpfel.o through
> >> > veristat, but unfortunately it is not libbpf-compatible.
> >> >
> >> > Is there some way to get a full verifier log for the failure above?
> >> > with log_level 2, if possible? If you can share it through Github Gist
> >> > or something like that, I'd really appreciate it. Thanks!
> >>
> >> Sure, here you go:
> >> https://gist.github.com/tohojo/31173d2bb07262a21393f76d9a45132d
> >
> > Thanks, this is very useful. And it's pretty clear what happens from
> > last few lines:
> >
> >     mark_precise: frame2: regs=r2 stack= before 1890: (dc) r2 = be64 r2
> >     mark_precise: frame2: regs=r0,r2 stack= before 1889: (73) *(u8
> > *)(r1 +47) = r3
> >
> > See how we add r0 to the regs set, while there is no r0 involved in
> > `r2 = be64 r2`? I think it's just a missing case of handling BPF_END
> > (and perhaps BPF_NEG as well) instructions in backtrack_insn(). Should
> > be a trivial fix, though ideally we should also add some test for this
> > as well.
>
> Sounds good, thank you for looking into it! Let me know if you need me
> to test a patch :)
>
> -Toke
>

Re: Hitting verifier backtracking bug on 6.5.5 kernel

[Shung-Hsi Yu]

On Tue, Oct 17, 2023 at 08:16:55AM -0400, Mohamed Mahmoud wrote:
> Any idea why the same verification errors are not seen when the
> program is attached with bpftool ?

Not sure why, but I've captured the verifier log during the successful tc
load here (using a slightly modified tc) on v6.5.4:
https://gist.github.com/shunghsiyu/b3bd6e4f4e1510e98a80491d50f3908b

    1890: (dc) r2 = be64 r2               ; frame2: R2_w=scalar()
    ; id->src_port = bpf_ntohs(udp->source);
    1891: (77) r2 >>= 56                  ; frame2: R2_w=scalar(umax=255,var_off=(0x0; 0xff))
    1892: (73) *(u8 *)(r1 +48) = r2
    mark_precise: frame2: last_idx 1892 first_idx 1883 subseq_idx -1 
    mark_precise: frame2: regs=r2 stack= before 1891: (77) r2 >>= 56
    mark_precise: frame2: regs=r2 stack= before 1890: (dc) r2 = be64 r2
    mark_precise: frame2: regs=r0,r2 stack= before 1889: (73) *(u8 *)(r1 +47) = r3
    mark_precise: frame2: regs=r0,r2 stack= before 1888: (dc) r3 = be16 r3
    mark_precise: frame2: regs=r0,r2 stack= before 1887: (bf) r3 = r2
    mark_precise: frame2: regs=r0,r2 stack= before 1886: (69) r2 = *(u16 *)(r7 +0)
    mark_precise: frame2: regs=r0 stack= before 1885: (2d) if r3 > r2 goto pc+23
    mark_precise: frame2: regs=r0 stack= before 1884: (07) r3 += 8
    mark_precise: frame2: regs=r0 stack= before 1883: (bf) r3 = r7
    mark_precise: frame2: parent state regs= stack=:  frame2: R1_r=fp-160 R2_r=pkt_end(off=0,imm=0) R3=17 R4=fp-96 R6=fp-96 R7_r=pkt(off=54,r=54,imm=0) R10=fp0
    mark_precise: frame1: parent state regs= stack=:  frame1: R6=ctx(off=0,imm=0) R7=1 R8=pkt_end(off=0,imm=0) R10=fp0 fp-56= fp-64=00000000 fp-72=00000000 fp-80=00000000 fp-88=mmmmmmmm fp-96=fp fp-104=??????00 fp-112=0000m000 fp-120= fp-128=mmmmmmmm fp-136=mmmmmmmm fp-144= fp-152=mmmmmmmm fp-160=mmmmm0mm
    mark_precise: frame0: parent state regs= stack=:  R10=fp0
    ; id->dst_port = bpf_ntohs(udp->dest);
    1893: (69) r2 = *(u16 *)(r7 +2)       ; frame2: R2_w=scalar(umax=65535,var_off=(0x0; 0xffff)) R7=pkt(off=54,r=62,imm=0)

Looks like r0 is also being incorrectly added the to the precise regs set
here; but I'm not sure why backtracking didn't go all the way back to "call
pc+1617" (which trigger the warning).

> On Tue, Oct 17, 2023 at 7:08 AM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
> >
> > Andrii Nakryiko <andrii.nakryiko@gmail.com> writes:
> >
> > > On Mon, Oct 16, 2023 at 12:37 PM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
> > >>
> > >> Andrii Nakryiko <andrii.nakryiko@gmail.com> writes:
> > >>
> > >> > On Thu, Oct 12, 2023 at 1:25 PM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
> > >> >>
> > >> >> Hi Andrii
> > >> >>
> > >> >> Mohamed ran into what appears to be a verifier bug related to your
> > >> >> commit:
> > >> >>
> > >> >> fde2a3882bd0 ("bpf: support precision propagation in the presence of subprogs")
> > >> >>
> > >> >> So I figured you'd be the person to ask about this :)
> > >> >>
> > >> >> The issue appears on a vanilla 6.5 kernel (on both 6.5.6 on Fedora 38,
> > >> >> and 6.5.5 on my Arch machine):
> > >> >>
> > >> >> INFO[0000] Verifier error: load program: bad address:
> > >> >>         1861: frame2: R1_w=fp-160 R2_w=pkt_end(off=0,imm=0) R3=scalar(umin=17,umax=255,var_off=(0x0; 0xff)) R4_w=fp-96 R6_w=fp-96 R7_w=pkt(off=34,r=34,imm=0) R10=fp0
> > >> >>         ; switch (protocol) {
> > >> >>         1861: (15) if r3 == 0x11 goto pc+22 1884: frame2: R1_w=fp-160 R2_w=pkt_end(off=0,imm=0) R3=17 R4_w=fp-96 R6_w=fp-96 R7_w=pkt(off=34,r=34,imm=0) R10=fp0
> > >> >>         ; if ((void *)udp + sizeof(*udp) <= data_end) {
> > >> >>         1884: (bf) r3 = r7                    ; frame2: R3_w=pkt(off=34,r=34,imm=0) R7_w=pkt(off=34,r=34,imm=0)
> > >> >>         1885: (07) r3 += 8                    ; frame2: R3_w=pkt(off=42,r=34,imm=0)
> > >> >>         ; if ((void *)udp + sizeof(*udp) <= data_end) {
> > >> >>         1886: (2d) if r3 > r2 goto pc+23      ; frame2: R2_w=pkt_end(off=0,imm=0) R3_w=pkt(off=42,r=42,imm=0)
> > >> >>         ; id->src_port = bpf_ntohs(udp->source);
> > >> >>         1887: (69) r2 = *(u16 *)(r7 +0)       ; frame2: R2_w=scalar(umax=65535,var_off=(0x0; 0xffff)) R7_w=pkt(off=34,r=42,imm=0)
> > >> >>         1888: (bf) r3 = r2                    ; frame2: R2_w=scalar(id=103,umax=65535,var_off=(0x0; 0xffff)) R3_w=scalar(id=103,umax=65535,var_off=(0x0; 0xffff))
> > >> >>         1889: (dc) r3 = be16 r3               ; frame2: R3_w=scalar()
> > >> >>         ; id->src_port = bpf_ntohs(udp->source);
> > >> >>         1890: (73) *(u8 *)(r1 +47) = r3       ; frame2: R1_w=fp-160 R3_w=scalar()
> > >> >>         ; id->src_port = bpf_ntohs(udp->source);
> > >> >>         1891: (dc) r2 = be64 r2               ; frame2: R2_w=scalar()
> > >> >>         ; id->src_port = bpf_ntohs(udp->source);
> > >> >>         1892: (77) r2 >>= 56                  ; frame2: R2_w=scalar(umax=255,var_off=(0x0; 0xff))
> > >> >>         1893: (73) *(u8 *)(r1 +48) = r2
> > >> >>         BUG regs 1
> > >> >>         processed 5121 insns (limit 1000000) max_states_per_insn 4 total_states 92 peak_states 90 mark_read 20
> > >> >>         (truncated)  component=ebpf.FlowFetcher
> > >> >>
> > >> >> Dmesg says:
> > >> >>
> > >> >> [252431.093126] verifier backtracking bug
> > >> >> [252431.093129] WARNING: CPU: 3 PID: 302245 at kernel/bpf/verifier.c:3533 __mark_chain_precision+0xe83/0x1090
> > >> >>
> > >> >>
> > >> >> The splat appears when trying to run the netobserv-ebpf-agent. Steps to
> > >> >> reproduce:
> > >> >>
> > >> >> git clone https://github.com/netobserv/netobserv-ebpf-agent
> > >> >> cd netobserv-ebpf-agent && make compile
> > >> >> sudo FLOWS_TARGET_HOST=127.0.0.1 FLOWS_TARGET_PORT=9999 ./bin/netobserv-ebpf-agent
> > >> >>
> > >> >> (It needs a 'make generate' before the compile to recompile the BPF
> > >> >> program itself, but that requires the Cilium bpf2go program to be
> > >> >> installed and there's a binary version checked into the tree so that is
> > >> >> not strictly necessary to reproduce the splat).
> > >> >>
> > >> >> That project uses the Cilium Go eBPF loader. Interestingly, loading the
> > >> >> same program using tc (with libbpf 1.2.2) works just fine:
> > >> >>
> > >> >> ip link add type veth
> > >> >> tc qdisc add dev veth0 clsact
> > >> >> tc filter add dev veth0 egress bpf direct-action obj pkg/ebpf/bpf_bpfel.o sec tc_egress
> > >> >>
> > >> >> So maybe there is some massaging of the object file that libbpf is doing
> > >> >> but the Go library isn't, that prevents this bug from triggering? I'm
> > >> >> only guessing here, I don't really know exactly what the Go library is
> > >> >> doing under the hood.
> > >> >>
> > >> >> Anyway, I guess this is a kernel bug in any case since that WARN() is
> > >> >> there; could you please take a look?
> > >> >>
> > >> >
> > >> > Yes, I tried. Unfortunately I can't build netobserv-ebpf-agent on my
> > >> > dev machine and can't run it. I tried to load bpf_bpfel.o through
> > >> > veristat, but unfortunately it is not libbpf-compatible.
> > >> >
> > >> > Is there some way to get a full verifier log for the failure above?
> > >> > with log_level 2, if possible? If you can share it through Github Gist
> > >> > or something like that, I'd really appreciate it. Thanks!
> > >>
> > >> Sure, here you go:
> > >> https://gist.github.com/tohojo/31173d2bb07262a21393f76d9a45132d
> > >
> > > Thanks, this is very useful. And it's pretty clear what happens from
> > > last few lines:
> > >
> > >     mark_precise: frame2: regs=r2 stack= before 1890: (dc) r2 = be64 r2
> > >     mark_precise: frame2: regs=r0,r2 stack= before 1889: (73) *(u8
> > > *)(r1 +47) = r3
> > >
> > > See how we add r0 to the regs set, while there is no r0 involved in
> > > `r2 = be64 r2`? I think it's just a missing case of handling BPF_END
> > > (and perhaps BPF_NEG as well) instructions in backtrack_insn(). Should
> > > be a trivial fix, though ideally we should also add some test for this
> > > as well.
> >
> > Sounds good, thank you for looking into it! Let me know if you need me
> > to test a patch :)
> >
> > -Toke
> >
> 

Re: Hitting verifier backtracking bug on 6.5.5 kernel

[Shung-Hsi Yu]

On Tue, Oct 17, 2023 at 01:08:25PM +0200, Toke Høiland-Jørgensen wrote:
> Andrii Nakryiko <andrii.nakryiko@gmail.com> writes:
> 
> > On Mon, Oct 16, 2023 at 12:37 PM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
> >>
> >> Andrii Nakryiko <andrii.nakryiko@gmail.com> writes:
> >>
> >> > On Thu, Oct 12, 2023 at 1:25 PM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
> >> >>
> >> >> Hi Andrii
> >> >>
> >> >> Mohamed ran into what appears to be a verifier bug related to your
> >> >> commit:
> >> >>
> >> >> fde2a3882bd0 ("bpf: support precision propagation in the presence of subprogs")
> >> >>
> >> >> So I figured you'd be the person to ask about this :)
> >> >>
> >> >> The issue appears on a vanilla 6.5 kernel (on both 6.5.6 on Fedora 38,
> >> >> and 6.5.5 on my Arch machine):
> >> >>
> >> >> INFO[0000] Verifier error: load program: bad address:
> >> >>         1861: frame2: R1_w=fp-160 R2_w=pkt_end(off=0,imm=0) R3=scalar(umin=17,umax=255,var_off=(0x0; 0xff)) R4_w=fp-96 R6_w=fp-96 R7_w=pkt(off=34,r=34,imm=0) R10=fp0
> >> >>         ; switch (protocol) {
> >> >>         1861: (15) if r3 == 0x11 goto pc+22 1884: frame2: R1_w=fp-160 R2_w=pkt_end(off=0,imm=0) R3=17 R4_w=fp-96 R6_w=fp-96 R7_w=pkt(off=34,r=34,imm=0) R10=fp0
> >> >>         ; if ((void *)udp + sizeof(*udp) <= data_end) {
> >> >>         1884: (bf) r3 = r7                    ; frame2: R3_w=pkt(off=34,r=34,imm=0) R7_w=pkt(off=34,r=34,imm=0)
> >> >>         1885: (07) r3 += 8                    ; frame2: R3_w=pkt(off=42,r=34,imm=0)
> >> >>         ; if ((void *)udp + sizeof(*udp) <= data_end) {
> >> >>         1886: (2d) if r3 > r2 goto pc+23      ; frame2: R2_w=pkt_end(off=0,imm=0) R3_w=pkt(off=42,r=42,imm=0)
> >> >>         ; id->src_port = bpf_ntohs(udp->source);
> >> >>         1887: (69) r2 = *(u16 *)(r7 +0)       ; frame2: R2_w=scalar(umax=65535,var_off=(0x0; 0xffff)) R7_w=pkt(off=34,r=42,imm=0)
> >> >>         1888: (bf) r3 = r2                    ; frame2: R2_w=scalar(id=103,umax=65535,var_off=(0x0; 0xffff)) R3_w=scalar(id=103,umax=65535,var_off=(0x0; 0xffff))
> >> >>         1889: (dc) r3 = be16 r3               ; frame2: R3_w=scalar()
> >> >>         ; id->src_port = bpf_ntohs(udp->source);
> >> >>         1890: (73) *(u8 *)(r1 +47) = r3       ; frame2: R1_w=fp-160 R3_w=scalar()
> >> >>         ; id->src_port = bpf_ntohs(udp->source);
> >> >>         1891: (dc) r2 = be64 r2               ; frame2: R2_w=scalar()
> >> >>         ; id->src_port = bpf_ntohs(udp->source);
> >> >>         1892: (77) r2 >>= 56                  ; frame2: R2_w=scalar(umax=255,var_off=(0x0; 0xff))
> >> >>         1893: (73) *(u8 *)(r1 +48) = r2
> >> >>         BUG regs 1
> >> >>         processed 5121 insns (limit 1000000) max_states_per_insn 4 total_states 92 peak_states 90 mark_read 20
> >> >>         (truncated)  component=ebpf.FlowFetcher
> >> >>
> >> >> Dmesg says:
> >> >>
> >> >> [252431.093126] verifier backtracking bug
> >> >> [252431.093129] WARNING: CPU: 3 PID: 302245 at kernel/bpf/verifier.c:3533 __mark_chain_precision+0xe83/0x1090
> >> >>
> >> >>
> >> >> The splat appears when trying to run the netobserv-ebpf-agent. Steps to
> >> >> reproduce:
> >> >>
> >> >> git clone https://github.com/netobserv/netobserv-ebpf-agent
> >> >> cd netobserv-ebpf-agent && make compile
> >> >> sudo FLOWS_TARGET_HOST=127.0.0.1 FLOWS_TARGET_PORT=9999 ./bin/netobserv-ebpf-agent
> >> >>
> >> >> (It needs a 'make generate' before the compile to recompile the BPF
> >> >> program itself, but that requires the Cilium bpf2go program to be
> >> >> installed and there's a binary version checked into the tree so that is
> >> >> not strictly necessary to reproduce the splat).
> >> >>
> >> >> That project uses the Cilium Go eBPF loader. Interestingly, loading the
> >> >> same program using tc (with libbpf 1.2.2) works just fine:
> >> >>
> >> >> ip link add type veth
> >> >> tc qdisc add dev veth0 clsact
> >> >> tc filter add dev veth0 egress bpf direct-action obj pkg/ebpf/bpf_bpfel.o sec tc_egress
> >> >>
> >> >> So maybe there is some massaging of the object file that libbpf is doing
> >> >> but the Go library isn't, that prevents this bug from triggering? I'm
> >> >> only guessing here, I don't really know exactly what the Go library is
> >> >> doing under the hood.
> >> >>
> >> >> Anyway, I guess this is a kernel bug in any case since that WARN() is
> >> >> there; could you please take a look?
> >> >>
> >> >
> >> > Yes, I tried. Unfortunately I can't build netobserv-ebpf-agent on my
> >> > dev machine and can't run it. I tried to load bpf_bpfel.o through
> >> > veristat, but unfortunately it is not libbpf-compatible.
> >> >
> >> > Is there some way to get a full verifier log for the failure above?
> >> > with log_level 2, if possible? If you can share it through Github Gist
> >> > or something like that, I'd really appreciate it. Thanks!
> >>
> >> Sure, here you go:
> >> https://gist.github.com/tohojo/31173d2bb07262a21393f76d9a45132d
> >
> > Thanks, this is very useful. And it's pretty clear what happens from
> > last few lines:
> >
> >     mark_precise: frame2: regs=r2 stack= before 1890: (dc) r2 = be64 r2
> >     mark_precise: frame2: regs=r0,r2 stack= before 1889: (73) *(u8
> > *)(r1 +47) = r3
> >
> > See how we add r0 to the regs set, while there is no r0 involved in
> > `r2 = be64 r2`? I think it's just a missing case of handling BPF_END
> > (and perhaps BPF_NEG as well) instructions in backtrack_insn(). Should
> > be a trivial fix, though ideally we should also add some test for this
> > as well.
> 
> Sounds good, thank you for looking into it! Let me know if you need me
> to test a patch :)

Patch based on Andrii's analysis.

Given that both BPF_END and BPF_NEG always operates on dst_reg itself
and that bt_is_reg_set(bt, dreg) was already checked I believe we can
just return with no futher action.

---
 kernel/bpf/verifier.c | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
index 9cdba4ce23d2..7e396288aaf0 100644
--- a/kernel/bpf/verifier.c
+++ b/kernel/bpf/verifier.c
@@ -3418,7 +3418,9 @@ static int backtrack_insn(struct bpf_verifier_env *env, int idx, int subseq_idx,
 	if (class == BPF_ALU || class == BPF_ALU64) {
 		if (!bt_is_reg_set(bt, dreg))
 			return 0;
-		if (opcode == BPF_MOV) {
+		if (opcode == BPF_END || opcode == BPF_NEG) {
+			return 0;
+		} else if (opcode == BPF_MOV) {
 			if (BPF_SRC(insn->code) == BPF_X) {
 				/* dreg = sreg
 				 * dreg needs precision after this insn
-- 
2.42.0

Re: Hitting verifier backtracking bug on 6.5.5 kernel

[Alexei Starovoitov]

On Tue, Oct 17, 2023 at 8:26 AM Shung-Hsi Yu <shung-hsi.yu@suse.com> wrote:
>
> >
> > Sounds good, thank you for looking into it! Let me know if you need me
> > to test a patch :)
>
> Patch based on Andrii's analysis.
>
> Given that both BPF_END and BPF_NEG always operates on dst_reg itself
> and that bt_is_reg_set(bt, dreg) was already checked I believe we can
> just return with no futher action.
>
> ---
>  kernel/bpf/verifier.c | 4 +++-
>  1 file changed, 3 insertions(+), 1 deletion(-)
>
> diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
> index 9cdba4ce23d2..7e396288aaf0 100644
> --- a/kernel/bpf/verifier.c
> +++ b/kernel/bpf/verifier.c
> @@ -3418,7 +3418,9 @@ static int backtrack_insn(struct bpf_verifier_env *env, int idx, int subseq_idx,
>         if (class == BPF_ALU || class == BPF_ALU64) {
>                 if (!bt_is_reg_set(bt, dreg))
>                         return 0;
> -               if (opcode == BPF_MOV) {
> +               if (opcode == BPF_END || opcode == BPF_NEG) {
> +                       return 0;
> +               } else if (opcode == BPF_MOV) {

lgtm. Pls send an official patch with a selftest.

Re: Hitting verifier backtracking bug on 6.5.5 kernel

[Toke Høiland-Jørgensen]

Shung-Hsi Yu <shung-hsi.yu@suse.com> writes:

> On Tue, Oct 17, 2023 at 01:08:25PM +0200, Toke Høiland-Jørgensen wrote:
>> Andrii Nakryiko <andrii.nakryiko@gmail.com> writes:
>> 
>> > On Mon, Oct 16, 2023 at 12:37 PM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
>> >>
>> >> Andrii Nakryiko <andrii.nakryiko@gmail.com> writes:
>> >>
>> >> > On Thu, Oct 12, 2023 at 1:25 PM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
>> >> >>
>> >> >> Hi Andrii
>> >> >>
>> >> >> Mohamed ran into what appears to be a verifier bug related to your
>> >> >> commit:
>> >> >>
>> >> >> fde2a3882bd0 ("bpf: support precision propagation in the presence of subprogs")
>> >> >>
>> >> >> So I figured you'd be the person to ask about this :)
>> >> >>
>> >> >> The issue appears on a vanilla 6.5 kernel (on both 6.5.6 on Fedora 38,
>> >> >> and 6.5.5 on my Arch machine):
>> >> >>
>> >> >> INFO[0000] Verifier error: load program: bad address:
>> >> >>         1861: frame2: R1_w=fp-160 R2_w=pkt_end(off=0,imm=0) R3=scalar(umin=17,umax=255,var_off=(0x0; 0xff)) R4_w=fp-96 R6_w=fp-96 R7_w=pkt(off=34,r=34,imm=0) R10=fp0
>> >> >>         ; switch (protocol) {
>> >> >>         1861: (15) if r3 == 0x11 goto pc+22 1884: frame2: R1_w=fp-160 R2_w=pkt_end(off=0,imm=0) R3=17 R4_w=fp-96 R6_w=fp-96 R7_w=pkt(off=34,r=34,imm=0) R10=fp0
>> >> >>         ; if ((void *)udp + sizeof(*udp) <= data_end) {
>> >> >>         1884: (bf) r3 = r7                    ; frame2: R3_w=pkt(off=34,r=34,imm=0) R7_w=pkt(off=34,r=34,imm=0)
>> >> >>         1885: (07) r3 += 8                    ; frame2: R3_w=pkt(off=42,r=34,imm=0)
>> >> >>         ; if ((void *)udp + sizeof(*udp) <= data_end) {
>> >> >>         1886: (2d) if r3 > r2 goto pc+23      ; frame2: R2_w=pkt_end(off=0,imm=0) R3_w=pkt(off=42,r=42,imm=0)
>> >> >>         ; id->src_port = bpf_ntohs(udp->source);
>> >> >>         1887: (69) r2 = *(u16 *)(r7 +0)       ; frame2: R2_w=scalar(umax=65535,var_off=(0x0; 0xffff)) R7_w=pkt(off=34,r=42,imm=0)
>> >> >>         1888: (bf) r3 = r2                    ; frame2: R2_w=scalar(id=103,umax=65535,var_off=(0x0; 0xffff)) R3_w=scalar(id=103,umax=65535,var_off=(0x0; 0xffff))
>> >> >>         1889: (dc) r3 = be16 r3               ; frame2: R3_w=scalar()
>> >> >>         ; id->src_port = bpf_ntohs(udp->source);
>> >> >>         1890: (73) *(u8 *)(r1 +47) = r3       ; frame2: R1_w=fp-160 R3_w=scalar()
>> >> >>         ; id->src_port = bpf_ntohs(udp->source);
>> >> >>         1891: (dc) r2 = be64 r2               ; frame2: R2_w=scalar()
>> >> >>         ; id->src_port = bpf_ntohs(udp->source);
>> >> >>         1892: (77) r2 >>= 56                  ; frame2: R2_w=scalar(umax=255,var_off=(0x0; 0xff))
>> >> >>         1893: (73) *(u8 *)(r1 +48) = r2
>> >> >>         BUG regs 1
>> >> >>         processed 5121 insns (limit 1000000) max_states_per_insn 4 total_states 92 peak_states 90 mark_read 20
>> >> >>         (truncated)  component=ebpf.FlowFetcher
>> >> >>
>> >> >> Dmesg says:
>> >> >>
>> >> >> [252431.093126] verifier backtracking bug
>> >> >> [252431.093129] WARNING: CPU: 3 PID: 302245 at kernel/bpf/verifier.c:3533 __mark_chain_precision+0xe83/0x1090
>> >> >>
>> >> >>
>> >> >> The splat appears when trying to run the netobserv-ebpf-agent. Steps to
>> >> >> reproduce:
>> >> >>
>> >> >> git clone https://github.com/netobserv/netobserv-ebpf-agent
>> >> >> cd netobserv-ebpf-agent && make compile
>> >> >> sudo FLOWS_TARGET_HOST=127.0.0.1 FLOWS_TARGET_PORT=9999 ./bin/netobserv-ebpf-agent
>> >> >>
>> >> >> (It needs a 'make generate' before the compile to recompile the BPF
>> >> >> program itself, but that requires the Cilium bpf2go program to be
>> >> >> installed and there's a binary version checked into the tree so that is
>> >> >> not strictly necessary to reproduce the splat).
>> >> >>
>> >> >> That project uses the Cilium Go eBPF loader. Interestingly, loading the
>> >> >> same program using tc (with libbpf 1.2.2) works just fine:
>> >> >>
>> >> >> ip link add type veth
>> >> >> tc qdisc add dev veth0 clsact
>> >> >> tc filter add dev veth0 egress bpf direct-action obj pkg/ebpf/bpf_bpfel.o sec tc_egress
>> >> >>
>> >> >> So maybe there is some massaging of the object file that libbpf is doing
>> >> >> but the Go library isn't, that prevents this bug from triggering? I'm
>> >> >> only guessing here, I don't really know exactly what the Go library is
>> >> >> doing under the hood.
>> >> >>
>> >> >> Anyway, I guess this is a kernel bug in any case since that WARN() is
>> >> >> there; could you please take a look?
>> >> >>
>> >> >
>> >> > Yes, I tried. Unfortunately I can't build netobserv-ebpf-agent on my
>> >> > dev machine and can't run it. I tried to load bpf_bpfel.o through
>> >> > veristat, but unfortunately it is not libbpf-compatible.
>> >> >
>> >> > Is there some way to get a full verifier log for the failure above?
>> >> > with log_level 2, if possible? If you can share it through Github Gist
>> >> > or something like that, I'd really appreciate it. Thanks!
>> >>
>> >> Sure, here you go:
>> >> https://gist.github.com/tohojo/31173d2bb07262a21393f76d9a45132d
>> >
>> > Thanks, this is very useful. And it's pretty clear what happens from
>> > last few lines:
>> >
>> >     mark_precise: frame2: regs=r2 stack= before 1890: (dc) r2 = be64 r2
>> >     mark_precise: frame2: regs=r0,r2 stack= before 1889: (73) *(u8
>> > *)(r1 +47) = r3
>> >
>> > See how we add r0 to the regs set, while there is no r0 involved in
>> > `r2 = be64 r2`? I think it's just a missing case of handling BPF_END
>> > (and perhaps BPF_NEG as well) instructions in backtrack_insn(). Should
>> > be a trivial fix, though ideally we should also add some test for this
>> > as well.
>> 
>> Sounds good, thank you for looking into it! Let me know if you need me
>> to test a patch :)
>
> Patch based on Andrii's analysis.
>
> Given that both BPF_END and BPF_NEG always operates on dst_reg itself
> and that bt_is_reg_set(bt, dreg) was already checked I believe we can
> just return with no futher action.

Alright, manually applied this to bpf-next and indeed this enables the
netobserv-bpf-agent to load successfully. Care to submit a formal patch?
In that case please add my:

Tested-by: Toke Høiland-Jørgensen <toke@redhat.com>

Thanks!

-Toke

Re: Hitting verifier backtracking bug on 6.5.5 kernel

[Toke Høiland-Jørgensen]

Toke Høiland-Jørgensen <toke@redhat.com> writes:

> Shung-Hsi Yu <shung-hsi.yu@suse.com> writes:
>
>> Patch based on Andrii's analysis.
>>
>> Given that both BPF_END and BPF_NEG always operates on dst_reg itself
>> and that bt_is_reg_set(bt, dreg) was already checked I believe we can
>> just return with no futher action.
>
> Alright, manually applied this to bpf-next and indeed this enables the
> netobserv-bpf-agent to load successfully. Care to submit a formal patch?
> In that case please add my:
>
> Tested-by: Toke Høiland-Jørgensen <toke@redhat.com>
>
> Thanks!

Friendly ping - are you planning to submit an official patch for this? :)

-Toke

Re: Hitting verifier backtracking bug on 6.5.5 kernel

[Shung-Hsi Yu]

On Fri, Oct 20, 2023 at 06:30:48PM +0200, Toke Høiland-Jørgensen wrote:
> Toke Høiland-Jørgensen <toke@redhat.com> writes:
> > Shung-Hsi Yu <shung-hsi.yu@suse.com> writes:
> >
> >> Patch based on Andrii's analysis.
> >>
> >> Given that both BPF_END and BPF_NEG always operates on dst_reg itself
> >> and that bt_is_reg_set(bt, dreg) was already checked I believe we can
> >> just return with no futher action.
> >
> > Alright, manually applied this to bpf-next and indeed this enables the
> > netobserv-bpf-agent to load successfully. Care to submit a formal patch?
> > In that case please add my:
> >
> > Tested-by: Toke Høiland-Jørgensen <toke@redhat.com>
> >
> > Thanks!
> 
> Friendly ping - are you planning to submit an official patch for this? :)

Yes, I do plan to send an offical one along with selftest as Alexei has
suggested. Once I've got my irrational fear of writing selftests overcame ;)

Should have it out before the end of this week.

Shung-Hsi

> -Toke

Re: Hitting verifier backtracking bug on 6.5.5 kernel

[Toke Høiland-Jørgensen]

Shung-Hsi Yu <shung-hsi.yu@suse.com> writes:

> On Fri, Oct 20, 2023 at 06:30:48PM +0200, Toke Høiland-Jørgensen wrote:
>> Toke Høiland-Jørgensen <toke@redhat.com> writes:
>> > Shung-Hsi Yu <shung-hsi.yu@suse.com> writes:
>> >
>> >> Patch based on Andrii's analysis.
>> >>
>> >> Given that both BPF_END and BPF_NEG always operates on dst_reg itself
>> >> and that bt_is_reg_set(bt, dreg) was already checked I believe we can
>> >> just return with no futher action.
>> >
>> > Alright, manually applied this to bpf-next and indeed this enables the
>> > netobserv-bpf-agent to load successfully. Care to submit a formal patch?
>> > In that case please add my:
>> >
>> > Tested-by: Toke Høiland-Jørgensen <toke@redhat.com>
>> >
>> > Thanks!
>> 
>> Friendly ping - are you planning to submit an official patch for this? :)
>
> Yes, I do plan to send an offical one along with selftest as Alexei has
> suggested. Once I've got my irrational fear of writing selftests overcame ;)
>
> Should have it out before the end of this week.

Alright great! Didn't mean to rush you, just wanted to double check that
you were planning to submit this :)

Thanks!

-Toke

Re: Hitting verifier backtracking bug on 6.5.5 kernel

[Shung-Hsi Yu]

On Tue, Oct 17, 2023 at 07:24:40PM +0200, Toke Høiland-Jørgensen wrote:
> Shung-Hsi Yu <shung-hsi.yu@suse.com> writes:
> > On Tue, Oct 17, 2023 at 01:08:25PM +0200, Toke Høiland-Jørgensen wrote:
> >> Andrii Nakryiko <andrii.nakryiko@gmail.com> writes:
> >> > On Mon, Oct 16, 2023 at 12:37 PM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
> >> >> Andrii Nakryiko <andrii.nakryiko@gmail.com> writes:
> >> >> > On Thu, Oct 12, 2023 at 1:25 PM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
> >> >> >>
> >> >> >> Hi Andrii
> >> >> >>
> >> >> >> Mohamed ran into what appears to be a verifier bug related to your
> >> >> >> commit:
> >> >> >>
> >> >> >> fde2a3882bd0 ("bpf: support precision propagation in the presence of subprogs")
> >> >> >>
> >> >> >> So I figured you'd be the person to ask about this :)
> >> >> >>
> >> >> >> The issue appears on a vanilla 6.5 kernel (on both 6.5.6 on Fedora 38,
> >> >> >> and 6.5.5 on my Arch machine):
> >> >> >>
> >> >> >> INFO[0000] Verifier error: load program: bad address:
> >> >> >>         1861: frame2: R1_w=fp-160 R2_w=pkt_end(off=0,imm=0) R3=scalar(umin=17,umax=255,var_off=(0x0; 0xff)) R4_w=fp-96 R6_w=fp-96 R7_w=pkt(off=34,r=34,imm=0) R10=fp0
> >> >> >>         ; switch (protocol) {
> >> >> >>         1861: (15) if r3 == 0x11 goto pc+22 1884: frame2: R1_w=fp-160 R2_w=pkt_end(off=0,imm=0) R3=17 R4_w=fp-96 R6_w=fp-96 R7_w=pkt(off=34,r=34,imm=0) R10=fp0
> >> >> >>         ; if ((void *)udp + sizeof(*udp) <= data_end) {
> >> >> >>         1884: (bf) r3 = r7                    ; frame2: R3_w=pkt(off=34,r=34,imm=0) R7_w=pkt(off=34,r=34,imm=0)
> >> >> >>         1885: (07) r3 += 8                    ; frame2: R3_w=pkt(off=42,r=34,imm=0)
> >> >> >>         ; if ((void *)udp + sizeof(*udp) <= data_end) {
> >> >> >>         1886: (2d) if r3 > r2 goto pc+23      ; frame2: R2_w=pkt_end(off=0,imm=0) R3_w=pkt(off=42,r=42,imm=0)
> >> >> >>         ; id->src_port = bpf_ntohs(udp->source);
> >> >> >>         1887: (69) r2 = *(u16 *)(r7 +0)       ; frame2: R2_w=scalar(umax=65535,var_off=(0x0; 0xffff)) R7_w=pkt(off=34,r=42,imm=0)
> >> >> >>         1888: (bf) r3 = r2                    ; frame2: R2_w=scalar(id=103,umax=65535,var_off=(0x0; 0xffff)) R3_w=scalar(id=103,umax=65535,var_off=(0x0; 0xffff))
> >> >> >>         1889: (dc) r3 = be16 r3               ; frame2: R3_w=scalar()
> >> >> >>         ; id->src_port = bpf_ntohs(udp->source);
> >> >> >>         1890: (73) *(u8 *)(r1 +47) = r3       ; frame2: R1_w=fp-160 R3_w=scalar()
> >> >> >>         ; id->src_port = bpf_ntohs(udp->source);
> >> >> >>         1891: (dc) r2 = be64 r2               ; frame2: R2_w=scalar()
> >> >> >>         ; id->src_port = bpf_ntohs(udp->source);
> >> >> >>         1892: (77) r2 >>= 56                  ; frame2: R2_w=scalar(umax=255,var_off=(0x0; 0xff))
> >> >> >>         1893: (73) *(u8 *)(r1 +48) = r2
> >> >> >>         BUG regs 1
> >> >> >>         processed 5121 insns (limit 1000000) max_states_per_insn 4 total_states 92 peak_states 90 mark_read 20
> >> >> >>         (truncated)  component=ebpf.FlowFetcher
> >> >> >>
> >> >> >> Dmesg says:
> >> >> >>
> >> >> >> [252431.093126] verifier backtracking bug
> >> >> >> [252431.093129] WARNING: CPU: 3 PID: 302245 at kernel/bpf/verifier.c:3533 __mark_chain_precision+0xe83/0x1090
> >> >> >>
> >> >> >> ...
> >> >> >
> >> >> > Is there some way to get a full verifier log for the failure above?
> >> >> > with log_level 2, if possible? If you can share it through Github Gist
> >> >> > or something like that, I'd really appreciate it. Thanks!
> >> >>
> >> >> Sure, here you go:
> >> >> https://gist.github.com/tohojo/31173d2bb07262a21393f76d9a45132d
> >> >
> >> > Thanks, this is very useful. And it's pretty clear what happens from
> >> > last few lines:
> >> >
> >> >     mark_precise: frame2: regs=r2 stack= before 1890: (dc) r2 = be64 r2
> >> >     mark_precise: frame2: regs=r0,r2 stack= before 1889: (73) *(u8
> >> > *)(r1 +47) = r3
> >> >
> >> > See how we add r0 to the regs set, while there is no r0 involved in
> >> > `r2 = be64 r2`? I think it's just a missing case of handling BPF_END
> >> > (and perhaps BPF_NEG as well) instructions in backtrack_insn(). Should
> >> > be a trivial fix, though ideally we should also add some test for this
> >> > as well.

Turns out the only case r0 is wrongly added to the regs set is with
BPF_ALU | BPF_TO_BE | BPF_END like the one seen here (only realize this
while working on selftests). All other cases are already handled correctly
because they happens to fall into the BPF_SRC(insn->code) == BPF_K == 0 case.

        } else {
                if (BPF_SRC(insn->code) == BPF_X) {
                        bt_set_reg(bt, sreg);
                }
                /* BPF_NEG, BPF_ALU | BPF_TO_LE | BPF_END, and
                 * BPF_ALU64 | BPF_END goes here in backtrack_insn()
                 */
        }

That said, having a "if (opcode == BPF_END || opcode == BPF_NEG)" check
still makes more sense, so I'm sticking with that.

RFC can be found at
 https://lore.kernel.org/bpf/20231030132145.20867-1-shung-hsi.yu@suse.com/

> >> Sounds good, thank you for looking into it! Let me know if you need me
> >> to test a patch :)
> >
> > Patch based on Andrii's analysis.
> >
> > Given that both BPF_END and BPF_NEG always operates on dst_reg itself
> > and that bt_is_reg_set(bt, dreg) was already checked I believe we can
> > just return with no futher action.
> 
> Alright, manually applied this to bpf-next and indeed this enables the
> netobserv-bpf-agent to load successfully. Care to submit a formal patch?
> In that case please add my:
> 
> Tested-by: Toke Høiland-Jørgensen <toke@redhat.com>
> 
> Thanks!
> 
> -Toke

Re: Hitting verifier backtracking bug on 6.5.5 kernel

[Toke Høiland-Jørgensen]

Shung-Hsi Yu <shung-hsi.yu@suse.com> writes:

> On Tue, Oct 17, 2023 at 07:24:40PM +0200, Toke Høiland-Jørgensen wrote:
>> Shung-Hsi Yu <shung-hsi.yu@suse.com> writes:
>> > On Tue, Oct 17, 2023 at 01:08:25PM +0200, Toke Høiland-Jørgensen wrote:
>> >> Andrii Nakryiko <andrii.nakryiko@gmail.com> writes:
>> >> > On Mon, Oct 16, 2023 at 12:37 PM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
>> >> >> Andrii Nakryiko <andrii.nakryiko@gmail.com> writes:
>> >> >> > On Thu, Oct 12, 2023 at 1:25 PM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
>> >> >> >>
>> >> >> >> Hi Andrii
>> >> >> >>
>> >> >> >> Mohamed ran into what appears to be a verifier bug related to your
>> >> >> >> commit:
>> >> >> >>
>> >> >> >> fde2a3882bd0 ("bpf: support precision propagation in the presence of subprogs")
>> >> >> >>
>> >> >> >> So I figured you'd be the person to ask about this :)
>> >> >> >>
>> >> >> >> The issue appears on a vanilla 6.5 kernel (on both 6.5.6 on Fedora 38,
>> >> >> >> and 6.5.5 on my Arch machine):
>> >> >> >>
>> >> >> >> INFO[0000] Verifier error: load program: bad address:
>> >> >> >>         1861: frame2: R1_w=fp-160 R2_w=pkt_end(off=0,imm=0) R3=scalar(umin=17,umax=255,var_off=(0x0; 0xff)) R4_w=fp-96 R6_w=fp-96 R7_w=pkt(off=34,r=34,imm=0) R10=fp0
>> >> >> >>         ; switch (protocol) {
>> >> >> >>         1861: (15) if r3 == 0x11 goto pc+22 1884: frame2: R1_w=fp-160 R2_w=pkt_end(off=0,imm=0) R3=17 R4_w=fp-96 R6_w=fp-96 R7_w=pkt(off=34,r=34,imm=0) R10=fp0
>> >> >> >>         ; if ((void *)udp + sizeof(*udp) <= data_end) {
>> >> >> >>         1884: (bf) r3 = r7                    ; frame2: R3_w=pkt(off=34,r=34,imm=0) R7_w=pkt(off=34,r=34,imm=0)
>> >> >> >>         1885: (07) r3 += 8                    ; frame2: R3_w=pkt(off=42,r=34,imm=0)
>> >> >> >>         ; if ((void *)udp + sizeof(*udp) <= data_end) {
>> >> >> >>         1886: (2d) if r3 > r2 goto pc+23      ; frame2: R2_w=pkt_end(off=0,imm=0) R3_w=pkt(off=42,r=42,imm=0)
>> >> >> >>         ; id->src_port = bpf_ntohs(udp->source);
>> >> >> >>         1887: (69) r2 = *(u16 *)(r7 +0)       ; frame2: R2_w=scalar(umax=65535,var_off=(0x0; 0xffff)) R7_w=pkt(off=34,r=42,imm=0)
>> >> >> >>         1888: (bf) r3 = r2                    ; frame2: R2_w=scalar(id=103,umax=65535,var_off=(0x0; 0xffff)) R3_w=scalar(id=103,umax=65535,var_off=(0x0; 0xffff))
>> >> >> >>         1889: (dc) r3 = be16 r3               ; frame2: R3_w=scalar()
>> >> >> >>         ; id->src_port = bpf_ntohs(udp->source);
>> >> >> >>         1890: (73) *(u8 *)(r1 +47) = r3       ; frame2: R1_w=fp-160 R3_w=scalar()
>> >> >> >>         ; id->src_port = bpf_ntohs(udp->source);
>> >> >> >>         1891: (dc) r2 = be64 r2               ; frame2: R2_w=scalar()
>> >> >> >>         ; id->src_port = bpf_ntohs(udp->source);
>> >> >> >>         1892: (77) r2 >>= 56                  ; frame2: R2_w=scalar(umax=255,var_off=(0x0; 0xff))
>> >> >> >>         1893: (73) *(u8 *)(r1 +48) = r2
>> >> >> >>         BUG regs 1
>> >> >> >>         processed 5121 insns (limit 1000000) max_states_per_insn 4 total_states 92 peak_states 90 mark_read 20
>> >> >> >>         (truncated)  component=ebpf.FlowFetcher
>> >> >> >>
>> >> >> >> Dmesg says:
>> >> >> >>
>> >> >> >> [252431.093126] verifier backtracking bug
>> >> >> >> [252431.093129] WARNING: CPU: 3 PID: 302245 at kernel/bpf/verifier.c:3533 __mark_chain_precision+0xe83/0x1090
>> >> >> >>
>> >> >> >> ...
>> >> >> >
>> >> >> > Is there some way to get a full verifier log for the failure above?
>> >> >> > with log_level 2, if possible? If you can share it through Github Gist
>> >> >> > or something like that, I'd really appreciate it. Thanks!
>> >> >>
>> >> >> Sure, here you go:
>> >> >> https://gist.github.com/tohojo/31173d2bb07262a21393f76d9a45132d
>> >> >
>> >> > Thanks, this is very useful. And it's pretty clear what happens from
>> >> > last few lines:
>> >> >
>> >> >     mark_precise: frame2: regs=r2 stack= before 1890: (dc) r2 = be64 r2
>> >> >     mark_precise: frame2: regs=r0,r2 stack= before 1889: (73) *(u8
>> >> > *)(r1 +47) = r3
>> >> >
>> >> > See how we add r0 to the regs set, while there is no r0 involved in
>> >> > `r2 = be64 r2`? I think it's just a missing case of handling BPF_END
>> >> > (and perhaps BPF_NEG as well) instructions in backtrack_insn(). Should
>> >> > be a trivial fix, though ideally we should also add some test for this
>> >> > as well.
>
> Turns out the only case r0 is wrongly added to the regs set is with
> BPF_ALU | BPF_TO_BE | BPF_END like the one seen here (only realize this
> while working on selftests). All other cases are already handled correctly
> because they happens to fall into the BPF_SRC(insn->code) == BPF_K == 0 case.
>
>         } else {
>                 if (BPF_SRC(insn->code) == BPF_X) {
>                         bt_set_reg(bt, sreg);
>                 }
>                 /* BPF_NEG, BPF_ALU | BPF_TO_LE | BPF_END, and
>                  * BPF_ALU64 | BPF_END goes here in backtrack_insn()
>                  */
>         }
>
> That said, having a "if (opcode == BPF_END || opcode == BPF_NEG)" check
> still makes more sense, so I'm sticking with that.
>
> RFC can be found at
>  https://lore.kernel.org/bpf/20231030132145.20867-1-shung-hsi.yu@suse.com/

Great, thanks for taking care of this! :)

-Toke

Re: Hitting verifier backtracking bug on 6.5.5 kernel

[Hengqi Chen]

On Fri, Oct 13, 2023 at 4:25 AM Toke Høiland-Jørgensen <toke@redhat.com> wrote:
>
> Hi Andrii
>
> Mohamed ran into what appears to be a verifier bug related to your
> commit:
>
> fde2a3882bd0 ("bpf: support precision propagation in the presence of subprogs")
>
> So I figured you'd be the person to ask about this :)
>
> The issue appears on a vanilla 6.5 kernel (on both 6.5.6 on Fedora 38,
> and 6.5.5 on my Arch machine):
>
> INFO[0000] Verifier error: load program: bad address:
>         1861: frame2: R1_w=fp-160 R2_w=pkt_end(off=0,imm=0) R3=scalar(umin=17,umax=255,var_off=(0x0; 0xff)) R4_w=fp-96 R6_w=fp-96 R7_w=pkt(off=34,r=34,imm=0) R10=fp0
>         ; switch (protocol) {
>         1861: (15) if r3 == 0x11 goto pc+22 1884: frame2: R1_w=fp-160 R2_w=pkt_end(off=0,imm=0) R3=17 R4_w=fp-96 R6_w=fp-96 R7_w=pkt(off=34,r=34,imm=0) R10=fp0
>         ; if ((void *)udp + sizeof(*udp) <= data_end) {
>         1884: (bf) r3 = r7                    ; frame2: R3_w=pkt(off=34,r=34,imm=0) R7_w=pkt(off=34,r=34,imm=0)
>         1885: (07) r3 += 8                    ; frame2: R3_w=pkt(off=42,r=34,imm=0)
>         ; if ((void *)udp + sizeof(*udp) <= data_end) {
>         1886: (2d) if r3 > r2 goto pc+23      ; frame2: R2_w=pkt_end(off=0,imm=0) R3_w=pkt(off=42,r=42,imm=0)
>         ; id->src_port = bpf_ntohs(udp->source);
>         1887: (69) r2 = *(u16 *)(r7 +0)       ; frame2: R2_w=scalar(umax=65535,var_off=(0x0; 0xffff)) R7_w=pkt(off=34,r=42,imm=0)
>         1888: (bf) r3 = r2                    ; frame2: R2_w=scalar(id=103,umax=65535,var_off=(0x0; 0xffff)) R3_w=scalar(id=103,umax=65535,var_off=(0x0; 0xffff))
>         1889: (dc) r3 = be16 r3               ; frame2: R3_w=scalar()
>         ; id->src_port = bpf_ntohs(udp->source);
>         1890: (73) *(u8 *)(r1 +47) = r3       ; frame2: R1_w=fp-160 R3_w=scalar()
>         ; id->src_port = bpf_ntohs(udp->source);
>         1891: (dc) r2 = be64 r2               ; frame2: R2_w=scalar()
>         ; id->src_port = bpf_ntohs(udp->source);
>         1892: (77) r2 >>= 56                  ; frame2: R2_w=scalar(umax=255,var_off=(0x0; 0xff))
>         1893: (73) *(u8 *)(r1 +48) = r2
>         BUG regs 1
>         processed 5121 insns (limit 1000000) max_states_per_insn 4 total_states 92 peak_states 90 mark_read 20
>         (truncated)  component=ebpf.FlowFetcher
>
> Dmesg says:
>
> [252431.093126] verifier backtracking bug
> [252431.093129] WARNING: CPU: 3 PID: 302245 at kernel/bpf/verifier.c:3533 __mark_chain_precision+0xe83/0x1090
>
>
> The splat appears when trying to run the netobserv-ebpf-agent. Steps to
> reproduce:
>
> git clone https://github.com/netobserv/netobserv-ebpf-agent
> cd netobserv-ebpf-agent && make compile
> sudo FLOWS_TARGET_HOST=127.0.0.1 FLOWS_TARGET_PORT=9999 ./bin/netobserv-ebpf-agent
>
> (It needs a 'make generate' before the compile to recompile the BPF
> program itself, but that requires the Cilium bpf2go program to be
> installed and there's a binary version checked into the tree so that is
> not strictly necessary to reproduce the splat).
>
> That project uses the Cilium Go eBPF loader. Interestingly, loading the
> same program using tc (with libbpf 1.2.2) works just fine:
>
> ip link add type veth
> tc qdisc add dev veth0 clsact
> tc filter add dev veth0 egress bpf direct-action obj pkg/ebpf/bpf_bpfel.o sec tc_egress
>
> So maybe there is some massaging of the object file that libbpf is doing
> but the Go library isn't, that prevents this bug from triggering? I'm
> only guessing here, I don't really know exactly what the Go library is
> doing under the hood.
>

Interesting, have you tried https://github.com/cilium/ebpf/pull/1159 ?

> Anyway, I guess this is a kernel bug in any case since that WARN() is
> there; could you please take a look?
>
> Thanks!
>
> -Toke
>
>