* R1 invalid mem access 'inv'
@ 2021-06-17 0:05 Vincent Li
2021-06-17 6:02 ` Yonghong Song
0 siblings, 1 reply; 12+ messages in thread
From: Vincent Li @ 2021-06-17 0:05 UTC (permalink / raw)
To: bpf
Hi BPF Experts,
I had a problem that verifier report "R1 invalid mem access 'inv'" when
I attempted to rewrite packet destination ethernet MAC address in Cilium
tunnel mode, I opened an issue
with detail here https://github.com/cilium/cilium/issues/16571:
I have couple of questions in general to try to understand the compiler,
BPF byte code, and the verifier.
1 Why the BPF byte code changes so much with my simple C code change
a: BPF byte code before C code change:
0000000000006068 <LBB12_410>:
3085: bf a2 00 00 00 00 00 00 r2 = r10
; tunnel = map_lookup_elem(&TUNNEL_MAP, key);
3086: 07 02 00 00 78 ff ff ff r2 += -136
3087: 18 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 r1 = 0 ll
3089: 85 00 00 00 01 00 00 00 call 1
; if (!tunnel)
3090: 15 00 06 01 00 00 00 00 if r0 == 0 goto +262 <LBB12_441>
; key.tunnel_id = seclabel;
3091: 18 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 r2 = 0 ll
3093: 67 02 00 00 20 00 00 00 r2 <<= 32
3094: 77 02 00 00 20 00 00 00 r2 >>= 32
3095: b7 01 00 00 06 00 00 00 r1 = 6
3096: 15 02 02 00 01 00 00 00 if r2 == 1 goto +2 <LBB12_413>
3097: 18 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 r1 = 0 ll
00000000000060d8 <LBB12_413>:
; return __encap_and_redirect_with_nodeid(ctx, tunnel->ip4,
seclabel, monitor);
b: BPF byte code after C code change:
the C code diff change:
diff --git a/bpf/lib/encap.h b/bpf/lib/encap.h
index dfd87bd82..19199429d 100644
--- a/bpf/lib/encap.h
+++ b/bpf/lib/encap.h
@@ -187,6 +187,8 @@ encap_and_redirect_lxc(struct __ctx_buff *ctx, __u32
tunnel_endpoint,
struct endpoint_key *key, __u32 seclabel, __u32
monitor)
{
struct endpoint_key *tunnel;
+#define VTEP_MAC { .addr = { 0xce, 0x72, 0xa7, 0x03, 0x88, 0x58 } }
+ union macaddr vtep_mac = VTEP_MAC;
if (tunnel_endpoint) {
#ifdef ENABLE_IPSEC
@@ -221,6 +223,8 @@ encap_and_redirect_lxc(struct __ctx_buff *ctx, __u32
tunnel_endpoint,
seclabel);
}
#endif
+ if (eth_store_daddr(ctx, (__u8 *) &vtep_mac.addr, 0) < 0)
+ return DROP_WRITE_ERROR;
return __encap_and_redirect_with_nodeid(ctx, tunnel->ip4,
seclabel, monitor);
}
the result BPF byte code
0000000000004468 <LBB3_274>:
2189: bf a2 00 00 00 00 00 00 r2 = r10
; tunnel = map_lookup_elem(&TUNNEL_MAP, key);
2190: 07 02 00 00 50 ff ff ff r2 += -176
2191: 18 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 r1 = 0 ll
2193: 85 00 00 00 01 00 00 00 call 1
2194: bf 07 00 00 00 00 00 00 r7 = r0
2195: 79 a6 48 ff 00 00 00 00 r6 = *(u64 *)(r10 - 184)
; if (!tunnel)
2196: 55 07 94 00 00 00 00 00 if r7 != 0 goto +148 <LBB3_289>
00000000000044a8 <LBB3_275>:
; __u8 new_ttl, ttl = ip4->ttl;
2197: 79 a1 38 ff 00 00 00 00 r1 = *(u64 *)(r10 - 200)
2198: 71 13 16 00 00 00 00 00 r3 = *(u8 *)(r1 + 22)
; if (ttl <= 1)
2199: 25 03 01 00 01 00 00 00 if r3 > 1 goto +1 <LBB3_277>
2200: 05 00 20 ff 00 00 00 00 goto -224 <LBB3_253>
You can see that:
before change: <LBB12_410>
after change <LBB3_274>
is different that <LBB12_410> has instructions 3091, 3092... but
<LBB3_274> end with instruction 2196
before change: <LBB12_413> follows <LBB12_410>
after change: <LBB3_275> follows <LBB3_274>
<LBB12_413> and <LBB3_275> is very much different
and <LBB3_275> instruction 2198 is the one with "R1 invalid mem access
'inv'"
Why <LBB3_275> follows <LBB3_274> ? from C code, <LBB3_275> is not close
to <LBB3_274>.
2, Can I assume the verifier is to simulate the order of BPF byte
code execution in run time, like if without any jump or goto in
<LBB3_274>, <LBB3_275> will be executed after <LBB3_274>?
Enterprise Network Engineer
F5 Networks Inc
https://www.youtube.com/c/VincentLi
^ permalink raw reply related [flat|nested] 12+ messages in thread
* Re: R1 invalid mem access 'inv'
2021-06-17 0:05 R1 invalid mem access 'inv' Vincent Li
@ 2021-06-17 6:02 ` Yonghong Song
2021-06-17 14:19 ` Vincent Li
0 siblings, 1 reply; 12+ messages in thread
From: Yonghong Song @ 2021-06-17 6:02 UTC (permalink / raw)
To: Vincent Li, bpf
On 6/16/21 5:05 PM, Vincent Li wrote:
> Hi BPF Experts,
>
> I had a problem that verifier report "R1 invalid mem access 'inv'" when
> I attempted to rewrite packet destination ethernet MAC address in Cilium
> tunnel mode, I opened an issue
> with detail here https://github.com/cilium/cilium/issues/16571:
>
> I have couple of questions in general to try to understand the compiler,
> BPF byte code, and the verifier.
>
> 1 Why the BPF byte code changes so much with my simple C code change
>
> a: BPF byte code before C code change:
>
> 0000000000006068 <LBB12_410>:
> 3085: bf a2 00 00 00 00 00 00 r2 = r10
> ; tunnel = map_lookup_elem(&TUNNEL_MAP, key);
> 3086: 07 02 00 00 78 ff ff ff r2 += -136
> 3087: 18 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 r1 = 0 ll
> 3089: 85 00 00 00 01 00 00 00 call 1
> ; if (!tunnel)
> 3090: 15 00 06 01 00 00 00 00 if r0 == 0 goto +262 <LBB12_441>
> ; key.tunnel_id = seclabel;
> 3091: 18 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 r2 = 0 ll
> 3093: 67 02 00 00 20 00 00 00 r2 <<= 32
> 3094: 77 02 00 00 20 00 00 00 r2 >>= 32
> 3095: b7 01 00 00 06 00 00 00 r1 = 6
> 3096: 15 02 02 00 01 00 00 00 if r2 == 1 goto +2 <LBB12_413>
> 3097: 18 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 r1 = 0 ll
>
> 00000000000060d8 <LBB12_413>:
> ; return __encap_and_redirect_with_nodeid(ctx, tunnel->ip4,
> seclabel, monitor);
>
>
> b: BPF byte code after C code change:
>
> the C code diff change:
>
> diff --git a/bpf/lib/encap.h b/bpf/lib/encap.h
> index dfd87bd82..19199429d 100644
> --- a/bpf/lib/encap.h
> +++ b/bpf/lib/encap.h
> @@ -187,6 +187,8 @@ encap_and_redirect_lxc(struct __ctx_buff *ctx, __u32
> tunnel_endpoint,
> struct endpoint_key *key, __u32 seclabel, __u32
> monitor)
> {
> struct endpoint_key *tunnel;
> +#define VTEP_MAC { .addr = { 0xce, 0x72, 0xa7, 0x03, 0x88, 0x58 } }
> + union macaddr vtep_mac = VTEP_MAC;
>
> if (tunnel_endpoint) {
> #ifdef ENABLE_IPSEC
> @@ -221,6 +223,8 @@ encap_and_redirect_lxc(struct __ctx_buff *ctx, __u32
> tunnel_endpoint,
> seclabel);
> }
> #endif
> + if (eth_store_daddr(ctx, (__u8 *) &vtep_mac.addr, 0) < 0)
> + return DROP_WRITE_ERROR;
> return __encap_and_redirect_with_nodeid(ctx, tunnel->ip4,
> seclabel, monitor);
> }
>
> the result BPF byte code
>
> 0000000000004468 <LBB3_274>:
> 2189: bf a2 00 00 00 00 00 00 r2 = r10
> ; tunnel = map_lookup_elem(&TUNNEL_MAP, key);
> 2190: 07 02 00 00 50 ff ff ff r2 += -176
> 2191: 18 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 r1 = 0 ll
> 2193: 85 00 00 00 01 00 00 00 call 1
> 2194: bf 07 00 00 00 00 00 00 r7 = r0
> 2195: 79 a6 48 ff 00 00 00 00 r6 = *(u64 *)(r10 - 184)
> ; if (!tunnel)
> 2196: 55 07 94 00 00 00 00 00 if r7 != 0 goto +148 <LBB3_289>
>
> 00000000000044a8 <LBB3_275>:
> ; __u8 new_ttl, ttl = ip4->ttl;
> 2197: 79 a1 38 ff 00 00 00 00 r1 = *(u64 *)(r10 - 200)
> 2198: 71 13 16 00 00 00 00 00 r3 = *(u8 *)(r1 + 22)
> ; if (ttl <= 1)
> 2199: 25 03 01 00 01 00 00 00 if r3 > 1 goto +1 <LBB3_277>
> 2200: 05 00 20 ff 00 00 00 00 goto -224 <LBB3_253>
>
>
> You can see that:
>
> before change: <LBB12_410>
> after change <LBB3_274>
>
> is different that <LBB12_410> has instructions 3091, 3092... but
> <LBB3_274> end with instruction 2196
>
> before change: <LBB12_413> follows <LBB12_410>
> after change: <LBB3_275> follows <LBB3_274>
>
> <LBB12_413> and <LBB3_275> is very much different
>
> and <LBB3_275> instruction 2198 is the one with "R1 invalid mem access
> 'inv'"
>
> Why <LBB3_275> follows <LBB3_274> ? from C code, <LBB3_275> is not close
> to <LBB3_274>.
The cilium code has a lot of functions inlined and after inlining, clang
may do reordering based on its internal heuristics. It is totally
possible slight code change may cause generated codes quite different.
Regarding to
> and <LBB3_275> instruction 2198 is the one with "R1 invalid mem access
> 'inv'"
> 00000000000044a8 <LBB3_275>:
> ; __u8 new_ttl, ttl = ip4->ttl;
> 2197: 79 a1 38 ff 00 00 00 00 r1 = *(u64 *)(r10 - 200)
> 2198: 71 13 16 00 00 00 00 00 r3 = *(u8 *)(r1 + 22)
> ; if (ttl <= 1)
> 2199: 25 03 01 00 01 00 00 00 if r3 > 1 goto +1 <LBB3_277>
> 2200: 05 00 20 ff 00 00 00 00 goto -224 <LBB3_253>
Looks like "ip4" is spilled on the stack. and maybe the stack
save/restore for "ip4" does not preserve its original type.
This mostly happens to old kernels, I think.
If you have verifier log, it may help identify issues easily.
>
>
> 2, Can I assume the verifier is to simulate the order of BPF byte
> code execution in run time, like if without any jump or goto in
> <LBB3_274>, <LBB3_275> will be executed after <LBB3_274>?
The verifier will try to verify both paths, jumping to LBB3_289
or fall back to LBB3_275.
>
>
>
> Enterprise Network Engineer
> F5 Networks Inc
> https://www.youtube.com/c/VincentLi
>
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: R1 invalid mem access 'inv'
2021-06-17 6:02 ` Yonghong Song
@ 2021-06-17 14:19 ` Vincent Li
2021-06-17 16:32 ` Yonghong Song
0 siblings, 1 reply; 12+ messages in thread
From: Vincent Li @ 2021-06-17 14:19 UTC (permalink / raw)
To: Yonghong Song; +Cc: Vincent Li, bpf
Hi Song,
Thank you for your response!
On Wed, 16 Jun 2021, Yonghong Song wrote:
>
>
> On 6/16/21 5:05 PM, Vincent Li wrote:
> > Hi BPF Experts,
> >
> > I had a problem that verifier report "R1 invalid mem access 'inv'" when
> > I attempted to rewrite packet destination ethernet MAC address in Cilium
> > tunnel mode, I opened an issue
> > with detail here https://github.com/cilium/cilium/issues/16571:
> >
> > I have couple of questions in general to try to understand the compiler,
> > BPF byte code, and the verifier.
> >
> > 1 Why the BPF byte code changes so much with my simple C code change
> >
> > a: BPF byte code before C code change:
> >
> > 0000000000006068 <LBB12_410>:
> > 3085: bf a2 00 00 00 00 00 00 r2 = r10
> > ; tunnel = map_lookup_elem(&TUNNEL_MAP, key);
> > 3086: 07 02 00 00 78 ff ff ff r2 += -136
> > 3087: 18 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 r1 = 0 ll
> > 3089: 85 00 00 00 01 00 00 00 call 1
> > ; if (!tunnel)
> > 3090: 15 00 06 01 00 00 00 00 if r0 == 0 goto +262 <LBB12_441>
> > ; key.tunnel_id = seclabel;
> > 3091: 18 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 r2 = 0 ll
> > 3093: 67 02 00 00 20 00 00 00 r2 <<= 32
> > 3094: 77 02 00 00 20 00 00 00 r2 >>= 32
> > 3095: b7 01 00 00 06 00 00 00 r1 = 6
> > 3096: 15 02 02 00 01 00 00 00 if r2 == 1 goto +2 <LBB12_413>
> > 3097: 18 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 r1 = 0 ll
> >
> > 00000000000060d8 <LBB12_413>:
> > ; return __encap_and_redirect_with_nodeid(ctx, tunnel->ip4,
> > seclabel, monitor);
> >
> >
> > b: BPF byte code after C code change:
> >
> > the C code diff change:
> >
> > diff --git a/bpf/lib/encap.h b/bpf/lib/encap.h
> > index dfd87bd82..19199429d 100644
> > --- a/bpf/lib/encap.h
> > +++ b/bpf/lib/encap.h
> > @@ -187,6 +187,8 @@ encap_and_redirect_lxc(struct __ctx_buff *ctx, __u32
> > tunnel_endpoint,
> > struct endpoint_key *key, __u32 seclabel, __u32
> > monitor)
> > {
> > struct endpoint_key *tunnel;
> > +#define VTEP_MAC { .addr = { 0xce, 0x72, 0xa7, 0x03, 0x88, 0x58 } }
> > + union macaddr vtep_mac = VTEP_MAC;
> > if (tunnel_endpoint) {
> > #ifdef ENABLE_IPSEC
> > @@ -221,6 +223,8 @@ encap_and_redirect_lxc(struct __ctx_buff *ctx, __u32
> > tunnel_endpoint,
> > seclabel);
> > }
> > #endif
> > + if (eth_store_daddr(ctx, (__u8 *) &vtep_mac.addr, 0) < 0)
> > + return DROP_WRITE_ERROR;
> > return __encap_and_redirect_with_nodeid(ctx, tunnel->ip4,
> > seclabel, monitor);
> > }
> >
> > the result BPF byte code
> >
> > 0000000000004468 <LBB3_274>:
> > 2189: bf a2 00 00 00 00 00 00 r2 = r10
> > ; tunnel = map_lookup_elem(&TUNNEL_MAP, key);
> > 2190: 07 02 00 00 50 ff ff ff r2 += -176
> > 2191: 18 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 r1 = 0 ll
> > 2193: 85 00 00 00 01 00 00 00 call 1
> > 2194: bf 07 00 00 00 00 00 00 r7 = r0
> > 2195: 79 a6 48 ff 00 00 00 00 r6 = *(u64 *)(r10 - 184)
> > ; if (!tunnel)
> > 2196: 55 07 94 00 00 00 00 00 if r7 != 0 goto +148 <LBB3_289>
> >
> > 00000000000044a8 <LBB3_275>:
> > ; __u8 new_ttl, ttl = ip4->ttl;
> > 2197: 79 a1 38 ff 00 00 00 00 r1 = *(u64 *)(r10 - 200)
> > 2198: 71 13 16 00 00 00 00 00 r3 = *(u8 *)(r1 + 22)
> > ; if (ttl <= 1)
> > 2199: 25 03 01 00 01 00 00 00 if r3 > 1 goto +1 <LBB3_277>
> > 2200: 05 00 20 ff 00 00 00 00 goto -224 <LBB3_253>
> >
> >
> > You can see that:
> >
> > before change: <LBB12_410>
> > after change <LBB3_274>
> >
> > is different that <LBB12_410> has instructions 3091, 3092... but
> > <LBB3_274> end with instruction 2196
> >
> > before change: <LBB12_413> follows <LBB12_410>
> > after change: <LBB3_275> follows <LBB3_274>
> >
> > <LBB12_413> and <LBB3_275> is very much different
> >
> > and <LBB3_275> instruction 2198 is the one with "R1 invalid mem access
> > 'inv'"
> >
> > Why <LBB3_275> follows <LBB3_274> ? from C code, <LBB3_275> is not close
> > to <LBB3_274>.
>
> The cilium code has a lot of functions inlined and after inlining, clang may
> do reordering based on its internal heuristics. It is totally possible slight
> code change may cause generated codes quite different.
>
> Regarding to
> > and <LBB3_275> instruction 2198 is the one with "R1 invalid mem access
> > 'inv'"
>
>
> > 00000000000044a8 <LBB3_275>:
> > ; __u8 new_ttl, ttl = ip4->ttl;
> > 2197: 79 a1 38 ff 00 00 00 00 r1 = *(u64 *)(r10 - 200)
> > 2198: 71 13 16 00 00 00 00 00 r3 = *(u8 *)(r1 + 22)
> > ; if (ttl <= 1)
> > 2199: 25 03 01 00 01 00 00 00 if r3 > 1 goto +1 <LBB3_277>
> > 2200: 05 00 20 ff 00 00 00 00 goto -224 <LBB3_253>
>
> Looks like "ip4" is spilled on the stack. and maybe the stack save/restore for
> "ip4" does not preserve its original type.
> This mostly happens to old kernels, I think.
>
the kernel 4.18 on Centos8, I also custom build most recent mainline git
kernel 5.13 on Centos8, I recall I got same invaid memory access
> If you have verifier log, it may help identify issues easily.
Here is the complete verifer log, I skipped the BTF part
level=warning msg="Prog section '2/7' rejected: Permission denied (13)!"
subsys=datapath-loader
level=warning msg=" - Type: 3" subsys=datapath-loader
level=warning msg=" - Attach Type: 0" subsys=datapath-loader
level=warning msg=" - Instructions: 2488 (0 over limit)"
subsys=datapath-loader
level=warning msg=" - License: GPL" subsys=datapath-loader
level=warning subsys=datapath-loader
level=warning msg="Verifier analysis:" subsys=datapath-loader
level=warning subsys=datapath-loader
level=warning msg="Skipped 158566 bytes, use 'verb' option for the full
verbose log." subsys=datapath-loader
level=warning msg="[...]" subsys=datapath-loader
level=warning msg="-136=????00mm fp-144=00000000 fp-152=0000mmmm
fp-160=????mmmm fp-168=mmmmmmmm fp-176=mmmmmmmm fp-184=ctx fp-192=mmmmmmmm
fp-200=inv fp-208=mmmmmmmm fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm
fp-240=inv128" subsys=datapath-loader
level=warning msg="2437: (0f) r1 += r8" subsys=datapath-loader
level=warning msg="2438: (7b) *(u64 *)(r0 +8) = r1" subsys=datapath-loader
level=warning msg=" R0_w=map_value(id=0,off=0,ks=8,vs=16,imm=0)
R1_w=inv(id=0) R6=ctx(id=0,off=0,imm=0)
R7=inv(id=0,umax_value=128,var_off=(0x0; 0xff))
R8=inv(id=0,umax_value=128,var_off=(0x0; 0xff)) R9=invP0 R10=fp0
fp-8=mmmmmmmm fp-16=????mmmm fp-24=mmmmmmmm fp-32=mmmmmmmm fp-40=mmmmmmmm
fp-48=mmmmmmmm fp-88=mmmmmmmm fp-96=00000000 fp-104=00000000
fp-112=??mmmmmm fp-120=mmmmmmmm fp-128=??mmmmmm fp-136=????00mm
fp-144=00000000 fp-152=0000mmmm fp-160=????mmmm fp-168=mmmmmmmm
fp-176=mmmmmmmm fp-184=ctx fp-192=mmmmmmmm fp-200=inv fp-208=mmmmmmmm
fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm fp-240=inv128"
subsys=datapath-loader
level=warning msg="2439: (05) goto pc+41" subsys=datapath-loader
level=warning msg="2481: (18) r2 = 0x5c7" subsys=datapath-loader
level=warning msg="2483: (67) r2 <<= 32" subsys=datapath-loader
level=warning msg="2484: (77) r2 >>= 32" subsys=datapath-loader
level=warning msg="2485: (b7) r1 = 6" subsys=datapath-loader
level=warning msg="2486: (15) if r2 == 0x1 goto pc-341"
subsys=datapath-loader
level=warning msg="last_idx 2486 first_idx 2481" subsys=datapath-loader
level=warning msg="regs=4 stack=0 before 2485: (b7) r1 = 6"
subsys=datapath-loader
level=warning msg="regs=4 stack=0 before 2484: (77) r2 >>= 32"
subsys=datapath-loader
level=warning msg="regs=4 stack=0 before 2483: (67) r2 <<= 32"
subsys=datapath-loader
level=warning msg="regs=4 stack=0 before 2481: (18) r2 = 0x5c7"
subsys=datapath-loader
level=warning msg="2487: (05) goto pc-344" subsys=datapath-loader
level=warning msg="2144: (18) r1 = 0x5c7" subsys=datapath-loader
level=warning msg="2146: (61) r2 = *(u32 *)(r6 +68)"
subsys=datapath-loader
level=warning msg="2147: (b7) r3 = 39" subsys=datapath-loader
level=warning msg="2148: (63) *(u32 *)(r10 -76) = r3"
subsys=datapath-loader
level=warning msg="2149: (b7) r3 = 1" subsys=datapath-loader
level=warning msg="2150: (6b) *(u16 *)(r10 -90) = r3"
subsys=datapath-loader
level=warning msg="2151: (63) *(u32 *)(r10 -96) = r8"
subsys=datapath-loader
level=warning msg="2152: (63) *(u32 *)(r10 -100) = r2"
subsys=datapath-loader
level=warning msg="2153: (18) r2 = 0x1d3" subsys=datapath-loader
level=warning msg="2155: (6b) *(u16 *)(r10 -102) = r2"
subsys=datapath-loader
level=warning msg="2156: (b7) r2 = 1028" subsys=datapath-loader
level=warning msg="2157: (6b) *(u16 *)(r10 -104) = r2"
subsys=datapath-loader
level=warning msg="2158: (b7) r2 = 0" subsys=datapath-loader
level=warning msg="2159: (63) *(u32 *)(r10 -80) = r2"
subsys=datapath-loader
level=warning msg="last_idx 2159 first_idx 2481" subsys=datapath-loader
level=warning msg="regs=4 stack=0 before 2158: (b7) r2 = 0"
subsys=datapath-loader
level=warning msg="2160: (63) *(u32 *)(r10 -84) = r2"
subsys=datapath-loader
level=warning msg="2161: (7b) *(u64 *)(r10 -72) = r2"
subsys=datapath-loader
level=warning msg="2162: (7b) *(u64 *)(r10 -64) = r2"
subsys=datapath-loader
level=warning msg="2163: (63) *(u32 *)(r10 -88) = r1"
subsys=datapath-loader
level=warning msg="2164: (6b) *(u16 *)(r10 -92) = r7"
subsys=datapath-loader
level=warning msg="2165: (67) r7 <<= 32" subsys=datapath-loader
level=warning msg="2166: (18) r1 = 0xffffffff" subsys=datapath-loader
level=warning msg="2168: (4f) r7 |= r1" subsys=datapath-loader
level=warning msg="2169: (bf) r4 = r10" subsys=datapath-loader
level=warning msg="2170: (07) r4 += -104" subsys=datapath-loader
level=warning msg="2171: (bf) r1 = r6" subsys=datapath-loader
level=warning msg="2172: (18) r2 = 0xffffa0c68cae1600"
subsys=datapath-loader
level=warning msg="2174: (bf) r3 = r7" subsys=datapath-loader
level=warning msg="2175: (b7) r5 = 48" subsys=datapath-loader
level=warning msg="2176: (85) call bpf_perf_event_output#25"
subsys=datapath-loader
level=warning msg="last_idx 2176 first_idx 2481" subsys=datapath-loader
level=warning msg="regs=20 stack=0 before 2175: (b7) r5 = 48"
subsys=datapath-loader
level=warning msg="2177: (b7) r1 = 39" subsys=datapath-loader
level=warning msg="2178: (b7) r2 = 0" subsys=datapath-loader
level=warning msg="2179: (85) call bpf_redirect#23" subsys=datapath-loader
level=warning msg="2180: (bf) r9 = r0" subsys=datapath-loader
level=warning msg="2181: (bf) r1 = r9" subsys=datapath-loader
level=warning msg="2182: (67) r1 <<= 32" subsys=datapath-loader
level=warning msg="2183: (77) r1 >>= 32" subsys=datapath-loader
level=warning msg="2184: (15) if r1 == 0x0 goto pc+57"
subsys=datapath-loader
level=warning msg=" R0_w=inv(id=0)
R1_w=inv(id=0,umax_value=2147483647,var_off=(0x0; 0x7fffffff))
R6=ctx(id=0,off=0,imm=0)
R7=inv(id=0,umin_value=4294967295,umax_value=1099511627775,var_off=(0xffffffff;
0xff00000000),s32_min_value=-1,s32_max_value=0,u32_max_value=0)
R8=inv(id=0,umax_value=128,var_off=(0x0; 0xff)) R9_w=inv(id=0) R10=fp0
fp-8=mmmmmmmm fp-16=????mmmm fp-24=mmmmmmmm fp-32=mmmmmmmm fp-40=mmmmmmmm
fp-48=mmmmmmmm fp-64=mmmmmmmm fp-72=mmmmmmmm fp-80=mmmmmmmm fp-88=mmmmmmmm
fp-96=mmmmmmmm fp-104=mmmmmmmm fp-112=??mmmmmm fp-120=mmmmmmmm
fp-128=??mmmmmm fp-136=????00mm fp-144=00000000 fp-152=0000mmmm
fp-160=????mmmm fp-168=mmmmmmmm fp-176=mmmmmmmm fp-184=ctx fp-192=mmmmmmmm
fp-200=inv fp-208=mmmmmmmm fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm
fp-240=inv128" subsys=datapath-loader
level=warning msg="2185: (18) r2 = 0xffffff60" subsys=datapath-loader
level=warning msg="2187: (1d) if r1 == r2 goto pc+9"
subsys=datapath-loader
level=warning subsys=datapath-loader
level=warning msg="from 2187 to 2197: R0=inv(id=0) R1=inv4294967136
R2=inv4294967136 R6=ctx(id=0,off=0,imm=0)
R7=inv(id=0,umin_value=4294967295,umax_value=1099511627775,var_off=(0xffffffff;
0xff00000000),s32_min_value=-1,s32_max_value=0,u32_max_value=0)
R8=inv(id=0,umax_value=128,var_off=(0x0; 0xff)) R9=inv(id=0) R10=fp0
fp-8=mmmmmmmm fp-16=????mmmm fp-24=mmmmmmmm fp-32=mmmmmmmm fp-40=mmmmmmmm
fp-48=mmmmmmmm fp-64=mmmmmmmm fp-72=mmmmmmmm fp-80=mmmmmmmm fp-88=mmmmmmmm
fp-96=mmmmmmmm fp-104=mmmmmmmm fp-112=??mmmmmm fp-120=mmmmmmmm
fp-128=??mmmmmm fp-136=????00mm fp-144=00000000 fp-152=0000mmmm
fp-160=????mmmm fp-168=mmmmmmmm fp-176=mmmmmmmm fp-184=ctx fp-192=mmmmmmmm
fp-200=inv fp-208=mmmmmmmm fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm
fp-240=inv128" subsys=datapath-loader
level=warning msg="2197: (79) r1 = *(u64 *)(r10 -200)"
subsys=datapath-loader
level=warning msg="2198: (71) r3 = *(u8 *)(r1 +22)" subsys=datapath-loader
level=warning msg="R1 invalid mem access 'inv'" subsys=datapath-loader
level=warning msg="processed 1802 insns (limit 1000000)
max_states_per_insn 4 total_states 103 peak_states 103 mark_read 49"
subsys=datapath-loader
level=warning subsys=datapath-loader
level=warning msg="Error filling program arrays!" subsys=datapath-loader
level=warning msg="Unable to load program" subsys=datapath-loader
> >
> >
> > 2, Can I assume the verifier is to simulate the order of BPF byte
> > code execution in run time, like if without any jump or goto in
> > <LBB3_274>, <LBB3_275> will be executed after <LBB3_274>?
>
> The verifier will try to verify both paths, jumping to LBB3_289
> or fall back to LBB3_275.
>
> >
> >
> >
> > Enterprise Network Engineer
> > F5 Networks Inc
> > https://www.youtube.com/c/VincentLi
> >
>
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: R1 invalid mem access 'inv'
2021-06-17 14:19 ` Vincent Li
@ 2021-06-17 16:32 ` Yonghong Song
2021-06-17 22:19 ` Vincent Li
0 siblings, 1 reply; 12+ messages in thread
From: Yonghong Song @ 2021-06-17 16:32 UTC (permalink / raw)
To: Vincent Li; +Cc: bpf
On 6/17/21 7:19 AM, Vincent Li wrote:
>
> Hi Song,
>
> Thank you for your response!
>
>
> On Wed, 16 Jun 2021, Yonghong Song wrote:
>
>>
>>
>> On 6/16/21 5:05 PM, Vincent Li wrote:
>>> Hi BPF Experts,
>>>
>>> I had a problem that verifier report "R1 invalid mem access 'inv'" when
>>> I attempted to rewrite packet destination ethernet MAC address in Cilium
>>> tunnel mode, I opened an issue
>>> with detail here https://github.com/cilium/cilium/issues/16571:
>>>
>>> I have couple of questions in general to try to understand the compiler,
>>> BPF byte code, and the verifier.
>>>
>>> 1 Why the BPF byte code changes so much with my simple C code change
>>>
>>> a: BPF byte code before C code change:
>>>
>>> 0000000000006068 <LBB12_410>:
>>> 3085: bf a2 00 00 00 00 00 00 r2 = r10
>>> ; tunnel = map_lookup_elem(&TUNNEL_MAP, key);
>>> 3086: 07 02 00 00 78 ff ff ff r2 += -136
>>> 3087: 18 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 r1 = 0 ll
>>> 3089: 85 00 00 00 01 00 00 00 call 1
>>> ; if (!tunnel)
>>> 3090: 15 00 06 01 00 00 00 00 if r0 == 0 goto +262 <LBB12_441>
>>> ; key.tunnel_id = seclabel;
>>> 3091: 18 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 r2 = 0 ll
>>> 3093: 67 02 00 00 20 00 00 00 r2 <<= 32
>>> 3094: 77 02 00 00 20 00 00 00 r2 >>= 32
>>> 3095: b7 01 00 00 06 00 00 00 r1 = 6
>>> 3096: 15 02 02 00 01 00 00 00 if r2 == 1 goto +2 <LBB12_413>
>>> 3097: 18 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 r1 = 0 ll
>>>
>>> 00000000000060d8 <LBB12_413>:
>>> ; return __encap_and_redirect_with_nodeid(ctx, tunnel->ip4,
>>> seclabel, monitor);
>>>
>>>
>>> b: BPF byte code after C code change:
>>>
>>> the C code diff change:
>>>
>>> diff --git a/bpf/lib/encap.h b/bpf/lib/encap.h
>>> index dfd87bd82..19199429d 100644
>>> --- a/bpf/lib/encap.h
>>> +++ b/bpf/lib/encap.h
>>> @@ -187,6 +187,8 @@ encap_and_redirect_lxc(struct __ctx_buff *ctx, __u32
>>> tunnel_endpoint,
>>> struct endpoint_key *key, __u32 seclabel, __u32
>>> monitor)
>>> {
>>> struct endpoint_key *tunnel;
>>> +#define VTEP_MAC { .addr = { 0xce, 0x72, 0xa7, 0x03, 0x88, 0x58 } }
>>> + union macaddr vtep_mac = VTEP_MAC;
>>> if (tunnel_endpoint) {
>>> #ifdef ENABLE_IPSEC
>>> @@ -221,6 +223,8 @@ encap_and_redirect_lxc(struct __ctx_buff *ctx, __u32
>>> tunnel_endpoint,
>>> seclabel);
>>> }
>>> #endif
>>> + if (eth_store_daddr(ctx, (__u8 *) &vtep_mac.addr, 0) < 0)
>>> + return DROP_WRITE_ERROR;
>>> return __encap_and_redirect_with_nodeid(ctx, tunnel->ip4,
>>> seclabel, monitor);
>>> }
>>>
>>> the result BPF byte code
>>>
>>> 0000000000004468 <LBB3_274>:
>>> 2189: bf a2 00 00 00 00 00 00 r2 = r10
>>> ; tunnel = map_lookup_elem(&TUNNEL_MAP, key);
>>> 2190: 07 02 00 00 50 ff ff ff r2 += -176
>>> 2191: 18 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 r1 = 0 ll
>>> 2193: 85 00 00 00 01 00 00 00 call 1
>>> 2194: bf 07 00 00 00 00 00 00 r7 = r0
>>> 2195: 79 a6 48 ff 00 00 00 00 r6 = *(u64 *)(r10 - 184)
>>> ; if (!tunnel)
>>> 2196: 55 07 94 00 00 00 00 00 if r7 != 0 goto +148 <LBB3_289>
>>>
>>> 00000000000044a8 <LBB3_275>:
>>> ; __u8 new_ttl, ttl = ip4->ttl;
>>> 2197: 79 a1 38 ff 00 00 00 00 r1 = *(u64 *)(r10 - 200)
>>> 2198: 71 13 16 00 00 00 00 00 r3 = *(u8 *)(r1 + 22)
>>> ; if (ttl <= 1)
>>> 2199: 25 03 01 00 01 00 00 00 if r3 > 1 goto +1 <LBB3_277>
>>> 2200: 05 00 20 ff 00 00 00 00 goto -224 <LBB3_253>
>>>
>>>
>>> You can see that:
>>>
>>> before change: <LBB12_410>
>>> after change <LBB3_274>
>>>
>>> is different that <LBB12_410> has instructions 3091, 3092... but
>>> <LBB3_274> end with instruction 2196
>>>
>>> before change: <LBB12_413> follows <LBB12_410>
>>> after change: <LBB3_275> follows <LBB3_274>
>>>
>>> <LBB12_413> and <LBB3_275> is very much different
>>>
>>> and <LBB3_275> instruction 2198 is the one with "R1 invalid mem access
>>> 'inv'"
>>>
>>> Why <LBB3_275> follows <LBB3_274> ? from C code, <LBB3_275> is not close
>>> to <LBB3_274>.
>>
>> The cilium code has a lot of functions inlined and after inlining, clang may
>> do reordering based on its internal heuristics. It is totally possible slight
>> code change may cause generated codes quite different.
>>
>> Regarding to
>>> and <LBB3_275> instruction 2198 is the one with "R1 invalid mem access
>>> 'inv'"
>>
>>
>>> 00000000000044a8 <LBB3_275>:
>>> ; __u8 new_ttl, ttl = ip4->ttl;
>>> 2197: 79 a1 38 ff 00 00 00 00 r1 = *(u64 *)(r10 - 200)
>>> 2198: 71 13 16 00 00 00 00 00 r3 = *(u8 *)(r1 + 22)
>>> ; if (ttl <= 1)
>>> 2199: 25 03 01 00 01 00 00 00 if r3 > 1 goto +1 <LBB3_277>
>>> 2200: 05 00 20 ff 00 00 00 00 goto -224 <LBB3_253>
>>
>> Looks like "ip4" is spilled on the stack. and maybe the stack save/restore for
>> "ip4" does not preserve its original type.
>> This mostly happens to old kernels, I think.
>>
>
> the kernel 4.18 on Centos8, I also custom build most recent mainline git
> kernel 5.13 on Centos8, I recall I got same invaid memory access
>
>> If you have verifier log, it may help identify issues easily.
>
> Here is the complete verifer log, I skipped the BTF part
>
> level=warning msg="Prog section '2/7' rejected: Permission denied (13)!"
> subsys=datapath-loader
> level=warning msg=" - Type: 3" subsys=datapath-loader
> level=warning msg=" - Attach Type: 0" subsys=datapath-loader
> level=warning msg=" - Instructions: 2488 (0 over limit)"
> subsys=datapath-loader
> level=warning msg=" - License: GPL" subsys=datapath-loader
> level=warning subsys=datapath-loader
> level=warning msg="Verifier analysis:" subsys=datapath-loader
> level=warning subsys=datapath-loader
> level=warning msg="Skipped 158566 bytes, use 'verb' option for the full
> verbose log." subsys=datapath-loader
> level=warning msg="[...]" subsys=datapath-loader
> level=warning msg="-136=????00mm fp-144=00000000 fp-152=0000mmmm
> fp-160=????mmmm fp-168=mmmmmmmm fp-176=mmmmmmmm fp-184=ctx fp-192=mmmmmmmm
> fp-200=inv fp-208=mmmmmmmm fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm
> fp-240=inv128" subsys=datapath-loader
> level=warning msg="2437: (0f) r1 += r8" subsys=datapath-loader
> level=warning msg="2438: (7b) *(u64 *)(r0 +8) = r1" subsys=datapath-loader
> level=warning msg=" R0_w=map_value(id=0,off=0,ks=8,vs=16,imm=0)
> R1_w=inv(id=0) R6=ctx(id=0,off=0,imm=0)
> R7=inv(id=0,umax_value=128,var_off=(0x0; 0xff))
> R8=inv(id=0,umax_value=128,var_off=(0x0; 0xff)) R9=invP0 R10=fp0
> fp-8=mmmmmmmm fp-16=????mmmm fp-24=mmmmmmmm fp-32=mmmmmmmm fp-40=mmmmmmmm
> fp-48=mmmmmmmm fp-88=mmmmmmmm fp-96=00000000 fp-104=00000000
> fp-112=??mmmmmm fp-120=mmmmmmmm fp-128=??mmmmmm fp-136=????00mm
> fp-144=00000000 fp-152=0000mmmm fp-160=????mmmm fp-168=mmmmmmmm
> fp-176=mmmmmmmm fp-184=ctx fp-192=mmmmmmmm fp-200=inv fp-208=mmmmmmmm
> fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm fp-240=inv128"
> subsys=datapath-loader
> level=warning msg="2439: (05) goto pc+41" subsys=datapath-loader
> level=warning msg="2481: (18) r2 = 0x5c7" subsys=datapath-loader
> level=warning msg="2483: (67) r2 <<= 32" subsys=datapath-loader
> level=warning msg="2484: (77) r2 >>= 32" subsys=datapath-loader
> level=warning msg="2485: (b7) r1 = 6" subsys=datapath-loader
> level=warning msg="2486: (15) if r2 == 0x1 goto pc-341"
> subsys=datapath-loader
> level=warning msg="last_idx 2486 first_idx 2481" subsys=datapath-loader
> level=warning msg="regs=4 stack=0 before 2485: (b7) r1 = 6"
> subsys=datapath-loader
> level=warning msg="regs=4 stack=0 before 2484: (77) r2 >>= 32"
> subsys=datapath-loader
> level=warning msg="regs=4 stack=0 before 2483: (67) r2 <<= 32"
> subsys=datapath-loader
> level=warning msg="regs=4 stack=0 before 2481: (18) r2 = 0x5c7"
> subsys=datapath-loader
> level=warning msg="2487: (05) goto pc-344" subsys=datapath-loader
> level=warning msg="2144: (18) r1 = 0x5c7" subsys=datapath-loader
> level=warning msg="2146: (61) r2 = *(u32 *)(r6 +68)"
> subsys=datapath-loader
> level=warning msg="2147: (b7) r3 = 39" subsys=datapath-loader
> level=warning msg="2148: (63) *(u32 *)(r10 -76) = r3"
> subsys=datapath-loader
> level=warning msg="2149: (b7) r3 = 1" subsys=datapath-loader
> level=warning msg="2150: (6b) *(u16 *)(r10 -90) = r3"
> subsys=datapath-loader
> level=warning msg="2151: (63) *(u32 *)(r10 -96) = r8"
> subsys=datapath-loader
> level=warning msg="2152: (63) *(u32 *)(r10 -100) = r2"
> subsys=datapath-loader
> level=warning msg="2153: (18) r2 = 0x1d3" subsys=datapath-loader
> level=warning msg="2155: (6b) *(u16 *)(r10 -102) = r2"
> subsys=datapath-loader
> level=warning msg="2156: (b7) r2 = 1028" subsys=datapath-loader
> level=warning msg="2157: (6b) *(u16 *)(r10 -104) = r2"
> subsys=datapath-loader
> level=warning msg="2158: (b7) r2 = 0" subsys=datapath-loader
> level=warning msg="2159: (63) *(u32 *)(r10 -80) = r2"
> subsys=datapath-loader
> level=warning msg="last_idx 2159 first_idx 2481" subsys=datapath-loader
> level=warning msg="regs=4 stack=0 before 2158: (b7) r2 = 0"
> subsys=datapath-loader
> level=warning msg="2160: (63) *(u32 *)(r10 -84) = r2"
> subsys=datapath-loader
> level=warning msg="2161: (7b) *(u64 *)(r10 -72) = r2"
> subsys=datapath-loader
> level=warning msg="2162: (7b) *(u64 *)(r10 -64) = r2"
> subsys=datapath-loader
> level=warning msg="2163: (63) *(u32 *)(r10 -88) = r1"
> subsys=datapath-loader
> level=warning msg="2164: (6b) *(u16 *)(r10 -92) = r7"
> subsys=datapath-loader
> level=warning msg="2165: (67) r7 <<= 32" subsys=datapath-loader
> level=warning msg="2166: (18) r1 = 0xffffffff" subsys=datapath-loader
> level=warning msg="2168: (4f) r7 |= r1" subsys=datapath-loader
> level=warning msg="2169: (bf) r4 = r10" subsys=datapath-loader
> level=warning msg="2170: (07) r4 += -104" subsys=datapath-loader
> level=warning msg="2171: (bf) r1 = r6" subsys=datapath-loader
> level=warning msg="2172: (18) r2 = 0xffffa0c68cae1600"
> subsys=datapath-loader
> level=warning msg="2174: (bf) r3 = r7" subsys=datapath-loader
> level=warning msg="2175: (b7) r5 = 48" subsys=datapath-loader
> level=warning msg="2176: (85) call bpf_perf_event_output#25"
> subsys=datapath-loader
> level=warning msg="last_idx 2176 first_idx 2481" subsys=datapath-loader
> level=warning msg="regs=20 stack=0 before 2175: (b7) r5 = 48"
> subsys=datapath-loader
> level=warning msg="2177: (b7) r1 = 39" subsys=datapath-loader
> level=warning msg="2178: (b7) r2 = 0" subsys=datapath-loader
> level=warning msg="2179: (85) call bpf_redirect#23" subsys=datapath-loader
> level=warning msg="2180: (bf) r9 = r0" subsys=datapath-loader
> level=warning msg="2181: (bf) r1 = r9" subsys=datapath-loader
> level=warning msg="2182: (67) r1 <<= 32" subsys=datapath-loader
> level=warning msg="2183: (77) r1 >>= 32" subsys=datapath-loader
> level=warning msg="2184: (15) if r1 == 0x0 goto pc+57"
> subsys=datapath-loader
> level=warning msg=" R0_w=inv(id=0)
> R1_w=inv(id=0,umax_value=2147483647,var_off=(0x0; 0x7fffffff))
> R6=ctx(id=0,off=0,imm=0)
> R7=inv(id=0,umin_value=4294967295,umax_value=1099511627775,var_off=(0xffffffff;
> 0xff00000000),s32_min_value=-1,s32_max_value=0,u32_max_value=0)
> R8=inv(id=0,umax_value=128,var_off=(0x0; 0xff)) R9_w=inv(id=0) R10=fp0
> fp-8=mmmmmmmm fp-16=????mmmm fp-24=mmmmmmmm fp-32=mmmmmmmm fp-40=mmmmmmmm
> fp-48=mmmmmmmm fp-64=mmmmmmmm fp-72=mmmmmmmm fp-80=mmmmmmmm fp-88=mmmmmmmm
> fp-96=mmmmmmmm fp-104=mmmmmmmm fp-112=??mmmmmm fp-120=mmmmmmmm
> fp-128=??mmmmmm fp-136=????00mm fp-144=00000000 fp-152=0000mmmm
> fp-160=????mmmm fp-168=mmmmmmmm fp-176=mmmmmmmm fp-184=ctx fp-192=mmmmmmmm
> fp-200=inv fp-208=mmmmmmmm fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm
> fp-240=inv128" subsys=datapath-loader
> level=warning msg="2185: (18) r2 = 0xffffff60" subsys=datapath-loader
> level=warning msg="2187: (1d) if r1 == r2 goto pc+9"
> subsys=datapath-loader
> level=warning subsys=datapath-loader
> level=warning msg="from 2187 to 2197: R0=inv(id=0) R1=inv4294967136
> R2=inv4294967136 R6=ctx(id=0,off=0,imm=0)
> R7=inv(id=0,umin_value=4294967295,umax_value=1099511627775,var_off=(0xffffffff;
> 0xff00000000),s32_min_value=-1,s32_max_value=0,u32_max_value=0)
> R8=inv(id=0,umax_value=128,var_off=(0x0; 0xff)) R9=inv(id=0) R10=fp0
> fp-8=mmmmmmmm fp-16=????mmmm fp-24=mmmmmmmm fp-32=mmmmmmmm fp-40=mmmmmmmm
> fp-48=mmmmmmmm fp-64=mmmmmmmm fp-72=mmmmmmmm fp-80=mmmmmmmm fp-88=mmmmmmmm
> fp-96=mmmmmmmm fp-104=mmmmmmmm fp-112=??mmmmmm fp-120=mmmmmmmm
> fp-128=??mmmmmm fp-136=????00mm fp-144=00000000 fp-152=0000mmmm
> fp-160=????mmmm fp-168=mmmmmmmm fp-176=mmmmmmmm fp-184=ctx fp-192=mmmmmmmm
> fp-200=inv fp-208=mmmmmmmm fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm
This is the problem. Here, we have "fp-200=inv" and
later on we have
r1 = *(u64 *)(r10 -200) // r1 is a unknown scalar
We cannot do the following operation
r3 = *(u8 *)(r1 +22)
since r1 is a unknown scalar and the verifier rightfully rejected
the program.
You need to examine complete log to find out why fp-200 stores
an "inv" (a unknown scalar).
> fp-240=inv128" subsys=datapath-loader
> level=warning msg="2197: (79) r1 = *(u64 *)(r10 -200)"
> subsys=datapath-loader
> level=warning msg="2198: (71) r3 = *(u8 *)(r1 +22)" subsys=datapath-loader
> level=warning msg="R1 invalid mem access 'inv'" subsys=datapath-loader
> level=warning msg="processed 1802 insns (limit 1000000)
> max_states_per_insn 4 total_states 103 peak_states 103 mark_read 49"
> subsys=datapath-loader
> level=warning subsys=datapath-loader
> level=warning msg="Error filling program arrays!" subsys=datapath-loader
> level=warning msg="Unable to load program" subsys=datapath-loader
>
>
>
>
>>>
>>>
>>> 2, Can I assume the verifier is to simulate the order of BPF byte
>>> code execution in run time, like if without any jump or goto in
>>> <LBB3_274>, <LBB3_275> will be executed after <LBB3_274>?
>>
>> The verifier will try to verify both paths, jumping to LBB3_289
>> or fall back to LBB3_275.
>>
>>>
>>>
>>>
>>> Enterprise Network Engineer
>>> F5 Networks Inc
>>> https://www.youtube.com/c/VincentLi
>>>
>>
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: R1 invalid mem access 'inv'
2021-06-17 16:32 ` Yonghong Song
@ 2021-06-17 22:19 ` Vincent Li
2021-06-18 0:51 ` Yonghong Song
0 siblings, 1 reply; 12+ messages in thread
From: Vincent Li @ 2021-06-17 22:19 UTC (permalink / raw)
To: Yonghong Song; +Cc: Vincent Li, bpf
On Thu, 17 Jun 2021, Yonghong Song wrote:
>
>
> On 6/17/21 7:19 AM, Vincent Li wrote:
> >
> > Hi Song,
> >
> > Thank you for your response!
> >
> >
> > On Wed, 16 Jun 2021, Yonghong Song wrote:
> >
> > >
> > >
> > > On 6/16/21 5:05 PM, Vincent Li wrote:
> > > > Hi BPF Experts,
> > > >
> > > > I had a problem that verifier report "R1 invalid mem access 'inv'" when
> > > > I attempted to rewrite packet destination ethernet MAC address in Cilium
> > > > tunnel mode, I opened an issue
> > > > with detail here https://github.com/cilium/cilium/issues/16571:
> > > >
> > > > I have couple of questions in general to try to understand the compiler,
> > > > BPF byte code, and the verifier.
> > > >
> > > > 1 Why the BPF byte code changes so much with my simple C code change
> > > >
> > > > a: BPF byte code before C code change:
> > > >
> > > > 0000000000006068 <LBB12_410>:
> > > > 3085: bf a2 00 00 00 00 00 00 r2 = r10
> > > > ; tunnel = map_lookup_elem(&TUNNEL_MAP, key);
> > > > 3086: 07 02 00 00 78 ff ff ff r2 += -136
> > > > 3087: 18 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 r1 = 0
> > > > ll
> > > > 3089: 85 00 00 00 01 00 00 00 call 1
> > > > ; if (!tunnel)
> > > > 3090: 15 00 06 01 00 00 00 00 if r0 == 0 goto +262
> > > > <LBB12_441>
> > > > ; key.tunnel_id = seclabel;
> > > > 3091: 18 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 r2 = 0
> > > > ll
> > > > 3093: 67 02 00 00 20 00 00 00 r2 <<= 32
> > > > 3094: 77 02 00 00 20 00 00 00 r2 >>= 32
> > > > 3095: b7 01 00 00 06 00 00 00 r1 = 6
> > > > 3096: 15 02 02 00 01 00 00 00 if r2 == 1 goto +2 <LBB12_413>
> > > > 3097: 18 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 r1 = 0
> > > > ll
> > > >
> > > > 00000000000060d8 <LBB12_413>:
> > > > ; return __encap_and_redirect_with_nodeid(ctx, tunnel->ip4,
> > > > seclabel, monitor);
> > > >
> > > >
> > > > b: BPF byte code after C code change:
> > > >
> > > > the C code diff change:
> > > >
> > > > diff --git a/bpf/lib/encap.h b/bpf/lib/encap.h
> > > > index dfd87bd82..19199429d 100644
> > > > --- a/bpf/lib/encap.h
> > > > +++ b/bpf/lib/encap.h
> > > > @@ -187,6 +187,8 @@ encap_and_redirect_lxc(struct __ctx_buff *ctx, __u32
> > > > tunnel_endpoint,
> > > > struct endpoint_key *key, __u32 seclabel, __u32
> > > > monitor)
> > > > {
> > > > struct endpoint_key *tunnel;
> > > > +#define VTEP_MAC { .addr = { 0xce, 0x72, 0xa7, 0x03, 0x88, 0x58 } }
> > > > + union macaddr vtep_mac = VTEP_MAC;
> > > > if (tunnel_endpoint) {
> > > > #ifdef ENABLE_IPSEC
> > > > @@ -221,6 +223,8 @@ encap_and_redirect_lxc(struct __ctx_buff *ctx, __u32
> > > > tunnel_endpoint,
> > > > seclabel);
> > > > }
> > > > #endif
> > > > + if (eth_store_daddr(ctx, (__u8 *) &vtep_mac.addr, 0) < 0)
> > > > + return DROP_WRITE_ERROR;
> > > > return __encap_and_redirect_with_nodeid(ctx, tunnel->ip4,
> > > > seclabel, monitor);
> > > > }
> > > >
> > > > the result BPF byte code
> > > >
> > > > 0000000000004468 <LBB3_274>:
> > > > 2189: bf a2 00 00 00 00 00 00 r2 = r10
> > > > ; tunnel = map_lookup_elem(&TUNNEL_MAP, key);
> > > > 2190: 07 02 00 00 50 ff ff ff r2 += -176
> > > > 2191: 18 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 r1 = 0
> > > > ll
> > > > 2193: 85 00 00 00 01 00 00 00 call 1
> > > > 2194: bf 07 00 00 00 00 00 00 r7 = r0
> > > > 2195: 79 a6 48 ff 00 00 00 00 r6 = *(u64 *)(r10 - 184)
> > > > ; if (!tunnel)
> > > > 2196: 55 07 94 00 00 00 00 00 if r7 != 0 goto +148
> > > > <LBB3_289>
> > > >
> > > > 00000000000044a8 <LBB3_275>:
> > > > ; __u8 new_ttl, ttl = ip4->ttl;
> > > > 2197: 79 a1 38 ff 00 00 00 00 r1 = *(u64 *)(r10 - 200)
> > > > 2198: 71 13 16 00 00 00 00 00 r3 = *(u8 *)(r1 + 22)
> > > > ; if (ttl <= 1)
> > > > 2199: 25 03 01 00 01 00 00 00 if r3 > 1 goto +1 <LBB3_277>
> > > > 2200: 05 00 20 ff 00 00 00 00 goto -224 <LBB3_253>
> > > >
> > > >
> > > > You can see that:
> > > >
> > > > before change: <LBB12_410>
> > > > after change <LBB3_274>
> > > >
> > > > is different that <LBB12_410> has instructions 3091, 3092... but
> > > > <LBB3_274> end with instruction 2196
> > > >
> > > > before change: <LBB12_413> follows <LBB12_410>
> > > > after change: <LBB3_275> follows <LBB3_274>
> > > >
> > > > <LBB12_413> and <LBB3_275> is very much different
> > > >
> > > > and <LBB3_275> instruction 2198 is the one with "R1 invalid mem access
> > > > 'inv'"
> > > >
> > > > Why <LBB3_275> follows <LBB3_274> ? from C code, <LBB3_275> is not close
> > > > to <LBB3_274>.
> > >
> > > The cilium code has a lot of functions inlined and after inlining, clang
> > > may
> > > do reordering based on its internal heuristics. It is totally possible
> > > slight
> > > code change may cause generated codes quite different.
> > >
> > > Regarding to
> > > > and <LBB3_275> instruction 2198 is the one with "R1 invalid mem access
> > > > 'inv'"
> > >
> > >
> > > > 00000000000044a8 <LBB3_275>:
> > > > ; __u8 new_ttl, ttl = ip4->ttl;
> > > > 2197: 79 a1 38 ff 00 00 00 00 r1 = *(u64 *)(r10 - 200)
> > > > 2198: 71 13 16 00 00 00 00 00 r3 = *(u8 *)(r1 + 22)
> > > > ; if (ttl <= 1)
> > > > 2199: 25 03 01 00 01 00 00 00 if r3 > 1 goto +1 <LBB3_277>
> > > > 2200: 05 00 20 ff 00 00 00 00 goto -224 <LBB3_253>
> > >
> > > Looks like "ip4" is spilled on the stack. and maybe the stack save/restore
> > > for
> > > "ip4" does not preserve its original type.
> > > This mostly happens to old kernels, I think.
> > >
> >
> > the kernel 4.18 on Centos8, I also custom build most recent mainline git
> > kernel 5.13 on Centos8, I recall I got same invaid memory access
> >
> > > If you have verifier log, it may help identify issues easily.
> >
> > Here is the complete verifer log, I skipped the BTF part
> >
> > level=warning msg="Prog section '2/7' rejected: Permission denied (13)!"
> > subsys=datapath-loader
> > level=warning msg=" - Type: 3" subsys=datapath-loader
> > level=warning msg=" - Attach Type: 0" subsys=datapath-loader
> > level=warning msg=" - Instructions: 2488 (0 over limit)"
> > subsys=datapath-loader
> > level=warning msg=" - License: GPL" subsys=datapath-loader
> > level=warning subsys=datapath-loader
> > level=warning msg="Verifier analysis:" subsys=datapath-loader
> > level=warning subsys=datapath-loader
> > level=warning msg="Skipped 158566 bytes, use 'verb' option for the full
> > verbose log." subsys=datapath-loader
> > level=warning msg="[...]" subsys=datapath-loader
> > level=warning msg="-136=????00mm fp-144=00000000 fp-152=0000mmmm
> > fp-160=????mmmm fp-168=mmmmmmmm fp-176=mmmmmmmm fp-184=ctx fp-192=mmmmmmmm
> > fp-200=inv fp-208=mmmmmmmm fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm
> > fp-240=inv128" subsys=datapath-loader
> > level=warning msg="2437: (0f) r1 += r8" subsys=datapath-loader
> > level=warning msg="2438: (7b) *(u64 *)(r0 +8) = r1" subsys=datapath-loader
> > level=warning msg=" R0_w=map_value(id=0,off=0,ks=8,vs=16,imm=0)
> > R1_w=inv(id=0) R6=ctx(id=0,off=0,imm=0)
> > R7=inv(id=0,umax_value=128,var_off=(0x0; 0xff))
> > R8=inv(id=0,umax_value=128,var_off=(0x0; 0xff)) R9=invP0 R10=fp0
> > fp-8=mmmmmmmm fp-16=????mmmm fp-24=mmmmmmmm fp-32=mmmmmmmm fp-40=mmmmmmmm
> > fp-48=mmmmmmmm fp-88=mmmmmmmm fp-96=00000000 fp-104=00000000
> > fp-112=??mmmmmm fp-120=mmmmmmmm fp-128=??mmmmmm fp-136=????00mm
> > fp-144=00000000 fp-152=0000mmmm fp-160=????mmmm fp-168=mmmmmmmm
> > fp-176=mmmmmmmm fp-184=ctx fp-192=mmmmmmmm fp-200=inv fp-208=mmmmmmmm
> > fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm fp-240=inv128"
> > subsys=datapath-loader
> > level=warning msg="2439: (05) goto pc+41" subsys=datapath-loader
> > level=warning msg="2481: (18) r2 = 0x5c7" subsys=datapath-loader
> > level=warning msg="2483: (67) r2 <<= 32" subsys=datapath-loader
> > level=warning msg="2484: (77) r2 >>= 32" subsys=datapath-loader
> > level=warning msg="2485: (b7) r1 = 6" subsys=datapath-loader
> > level=warning msg="2486: (15) if r2 == 0x1 goto pc-341"
> > subsys=datapath-loader
> > level=warning msg="last_idx 2486 first_idx 2481" subsys=datapath-loader
> > level=warning msg="regs=4 stack=0 before 2485: (b7) r1 = 6"
> > subsys=datapath-loader
> > level=warning msg="regs=4 stack=0 before 2484: (77) r2 >>= 32"
> > subsys=datapath-loader
> > level=warning msg="regs=4 stack=0 before 2483: (67) r2 <<= 32"
> > subsys=datapath-loader
> > level=warning msg="regs=4 stack=0 before 2481: (18) r2 = 0x5c7"
> > subsys=datapath-loader
> > level=warning msg="2487: (05) goto pc-344" subsys=datapath-loader
> > level=warning msg="2144: (18) r1 = 0x5c7" subsys=datapath-loader
> > level=warning msg="2146: (61) r2 = *(u32 *)(r6 +68)"
> > subsys=datapath-loader
> > level=warning msg="2147: (b7) r3 = 39" subsys=datapath-loader
> > level=warning msg="2148: (63) *(u32 *)(r10 -76) = r3"
> > subsys=datapath-loader
> > level=warning msg="2149: (b7) r3 = 1" subsys=datapath-loader
> > level=warning msg="2150: (6b) *(u16 *)(r10 -90) = r3"
> > subsys=datapath-loader
> > level=warning msg="2151: (63) *(u32 *)(r10 -96) = r8"
> > subsys=datapath-loader
> > level=warning msg="2152: (63) *(u32 *)(r10 -100) = r2"
> > subsys=datapath-loader
> > level=warning msg="2153: (18) r2 = 0x1d3" subsys=datapath-loader
> > level=warning msg="2155: (6b) *(u16 *)(r10 -102) = r2"
> > subsys=datapath-loader
> > level=warning msg="2156: (b7) r2 = 1028" subsys=datapath-loader
> > level=warning msg="2157: (6b) *(u16 *)(r10 -104) = r2"
> > subsys=datapath-loader
> > level=warning msg="2158: (b7) r2 = 0" subsys=datapath-loader
> > level=warning msg="2159: (63) *(u32 *)(r10 -80) = r2"
> > subsys=datapath-loader
> > level=warning msg="last_idx 2159 first_idx 2481" subsys=datapath-loader
> > level=warning msg="regs=4 stack=0 before 2158: (b7) r2 = 0"
> > subsys=datapath-loader
> > level=warning msg="2160: (63) *(u32 *)(r10 -84) = r2"
> > subsys=datapath-loader
> > level=warning msg="2161: (7b) *(u64 *)(r10 -72) = r2"
> > subsys=datapath-loader
> > level=warning msg="2162: (7b) *(u64 *)(r10 -64) = r2"
> > subsys=datapath-loader
> > level=warning msg="2163: (63) *(u32 *)(r10 -88) = r1"
> > subsys=datapath-loader
> > level=warning msg="2164: (6b) *(u16 *)(r10 -92) = r7"
> > subsys=datapath-loader
> > level=warning msg="2165: (67) r7 <<= 32" subsys=datapath-loader
> > level=warning msg="2166: (18) r1 = 0xffffffff" subsys=datapath-loader
> > level=warning msg="2168: (4f) r7 |= r1" subsys=datapath-loader
> > level=warning msg="2169: (bf) r4 = r10" subsys=datapath-loader
> > level=warning msg="2170: (07) r4 += -104" subsys=datapath-loader
> > level=warning msg="2171: (bf) r1 = r6" subsys=datapath-loader
> > level=warning msg="2172: (18) r2 = 0xffffa0c68cae1600"
> > subsys=datapath-loader
> > level=warning msg="2174: (bf) r3 = r7" subsys=datapath-loader
> > level=warning msg="2175: (b7) r5 = 48" subsys=datapath-loader
> > level=warning msg="2176: (85) call bpf_perf_event_output#25"
> > subsys=datapath-loader
> > level=warning msg="last_idx 2176 first_idx 2481" subsys=datapath-loader
> > level=warning msg="regs=20 stack=0 before 2175: (b7) r5 = 48"
> > subsys=datapath-loader
> > level=warning msg="2177: (b7) r1 = 39" subsys=datapath-loader
> > level=warning msg="2178: (b7) r2 = 0" subsys=datapath-loader
> > level=warning msg="2179: (85) call bpf_redirect#23" subsys=datapath-loader
> > level=warning msg="2180: (bf) r9 = r0" subsys=datapath-loader
> > level=warning msg="2181: (bf) r1 = r9" subsys=datapath-loader
> > level=warning msg="2182: (67) r1 <<= 32" subsys=datapath-loader
> > level=warning msg="2183: (77) r1 >>= 32" subsys=datapath-loader
> > level=warning msg="2184: (15) if r1 == 0x0 goto pc+57"
> > subsys=datapath-loader
> > level=warning msg=" R0_w=inv(id=0)
> > R1_w=inv(id=0,umax_value=2147483647,var_off=(0x0; 0x7fffffff))
> > R6=ctx(id=0,off=0,imm=0)
> > R7=inv(id=0,umin_value=4294967295,umax_value=1099511627775,var_off=(0xffffffff;
> > 0xff00000000),s32_min_value=-1,s32_max_value=0,u32_max_value=0)
> > R8=inv(id=0,umax_value=128,var_off=(0x0; 0xff)) R9_w=inv(id=0) R10=fp0
> > fp-8=mmmmmmmm fp-16=????mmmm fp-24=mmmmmmmm fp-32=mmmmmmmm fp-40=mmmmmmmm
> > fp-48=mmmmmmmm fp-64=mmmmmmmm fp-72=mmmmmmmm fp-80=mmmmmmmm fp-88=mmmmmmmm
> > fp-96=mmmmmmmm fp-104=mmmmmmmm fp-112=??mmmmmm fp-120=mmmmmmmm
> > fp-128=??mmmmmm fp-136=????00mm fp-144=00000000 fp-152=0000mmmm
> > fp-160=????mmmm fp-168=mmmmmmmm fp-176=mmmmmmmm fp-184=ctx fp-192=mmmmmmmm
> > fp-200=inv fp-208=mmmmmmmm fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm
> > fp-240=inv128" subsys=datapath-loader
> > level=warning msg="2185: (18) r2 = 0xffffff60" subsys=datapath-loader
> > level=warning msg="2187: (1d) if r1 == r2 goto pc+9"
> > subsys=datapath-loader
> > level=warning subsys=datapath-loader
> > level=warning msg="from 2187 to 2197: R0=inv(id=0) R1=inv4294967136
> > R2=inv4294967136 R6=ctx(id=0,off=0,imm=0)
> > R7=inv(id=0,umin_value=4294967295,umax_value=1099511627775,var_off=(0xffffffff;
> > 0xff00000000),s32_min_value=-1,s32_max_value=0,u32_max_value=0)
> > R8=inv(id=0,umax_value=128,var_off=(0x0; 0xff)) R9=inv(id=0) R10=fp0
> > fp-8=mmmmmmmm fp-16=????mmmm fp-24=mmmmmmmm fp-32=mmmmmmmm fp-40=mmmmmmmm
> > fp-48=mmmmmmmm fp-64=mmmmmmmm fp-72=mmmmmmmm fp-80=mmmmmmmm fp-88=mmmmmmmm
> > fp-96=mmmmmmmm fp-104=mmmmmmmm fp-112=??mmmmmm fp-120=mmmmmmmm
> > fp-128=??mmmmmm fp-136=????00mm fp-144=00000000 fp-152=0000mmmm
> > fp-160=????mmmm fp-168=mmmmmmmm fp-176=mmmmmmmm fp-184=ctx fp-192=mmmmmmmm
> > fp-200=inv fp-208=mmmmmmmm fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm
>
> This is the problem. Here, we have "fp-200=inv" and
> later on we have
> r1 = *(u64 *)(r10 -200) // r1 is a unknown scalar
>
> We cannot do the following operation
> r3 = *(u8 *)(r1 +22)
> since r1 is a unknown scalar and the verifier rightfully rejected
> the program.
>
> You need to examine complete log to find out why fp-200 stores
> an "inv" (a unknown scalar).
I guess you mean the complete log starting from the prog section 2/7 from
verifier, if so, it seems fp-200 started with "inv"
level=warning msg="Prog section '2/7' rejected: Permission denied (13)!"
subsys=datapath-loader
level=warning msg="-136=????00mm fp-144=00000000 fp-152=0000mmmm
fp-160=????mmmm fp-168=mmmmmmmm fp-176=mmmmmmmm fp-184=ctx fp-192=mmmmmmmm
fp-200=inv fp-208=mmmmmmmm fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm
fp-240=inv128" subsys=datapath-loader
and I don't see fp-200 ever changed to something else after, maybe I am
reading it wrong
>
> > fp-240=inv128" subsys=datapath-loader
> > level=warning msg="2197: (79) r1 = *(u64 *)(r10 -200)"
> > subsys=datapath-loader
> > level=warning msg="2198: (71) r3 = *(u8 *)(r1 +22)" subsys=datapath-loader
> > level=warning msg="R1 invalid mem access 'inv'" subsys=datapath-loader
> > level=warning msg="processed 1802 insns (limit 1000000)
> > max_states_per_insn 4 total_states 103 peak_states 103 mark_read 49"
> > subsys=datapath-loader
> > level=warning subsys=datapath-loader
> > level=warning msg="Error filling program arrays!" subsys=datapath-loader
> > level=warning msg="Unable to load program" subsys=datapath-loader
> >
> >
> >
> > > >
> > > >
> > > > 2, Can I assume the verifier is to simulate the order of BPF byte
> > > > code execution in run time, like if without any jump or goto in
> > > > <LBB3_274>, <LBB3_275> will be executed after <LBB3_274>?
> > >
> > > The verifier will try to verify both paths, jumping to LBB3_289
> > > or fall back to LBB3_275.
> > >
> > > >
> > > >
> > > >
> > > > Enterprise Network Engineer
> > > > F5 Networks Inc
> > > > https://www.youtube.com/c/VincentLi
> > > >
> > >
>
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: R1 invalid mem access 'inv'
2021-06-17 22:19 ` Vincent Li
@ 2021-06-18 0:51 ` Yonghong Song
2021-06-18 3:58 ` Vincent Li
0 siblings, 1 reply; 12+ messages in thread
From: Yonghong Song @ 2021-06-18 0:51 UTC (permalink / raw)
To: Vincent Li; +Cc: bpf
On 6/17/21 3:19 PM, Vincent Li wrote:
>
>
> On Thu, 17 Jun 2021, Yonghong Song wrote:
>
>>
>>
>> On 6/17/21 7:19 AM, Vincent Li wrote:
>>>
>>> Hi Song,
>>>
>>> Thank you for your response!
>>>
>>>
>>> On Wed, 16 Jun 2021, Yonghong Song wrote:
>>>
>>>>
>>>>
>>>> On 6/16/21 5:05 PM, Vincent Li wrote:
>>>>> Hi BPF Experts,
>>>>>
>>>>> I had a problem that verifier report "R1 invalid mem access 'inv'" when
>>>>> I attempted to rewrite packet destination ethernet MAC address in Cilium
>>>>> tunnel mode, I opened an issue
>>>>> with detail here https://github.com/cilium/cilium/issues/16571:
>>>>>
>>>>> I have couple of questions in general to try to understand the compiler,
>>>>> BPF byte code, and the verifier.
>>>>>
>>>>> 1 Why the BPF byte code changes so much with my simple C code change
>>>>>
>>>>> a: BPF byte code before C code change:
>>>>>
>>>>> 0000000000006068 <LBB12_410>:
>>>>> 3085: bf a2 00 00 00 00 00 00 r2 = r10
>>>>> ; tunnel = map_lookup_elem(&TUNNEL_MAP, key);
>>>>> 3086: 07 02 00 00 78 ff ff ff r2 += -136
>>>>> 3087: 18 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 r1 = 0
>>>>> ll
>>>>> 3089: 85 00 00 00 01 00 00 00 call 1
>>>>> ; if (!tunnel)
>>>>> 3090: 15 00 06 01 00 00 00 00 if r0 == 0 goto +262
>>>>> <LBB12_441>
>>>>> ; key.tunnel_id = seclabel;
>>>>> 3091: 18 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 r2 = 0
>>>>> ll
>>>>> 3093: 67 02 00 00 20 00 00 00 r2 <<= 32
>>>>> 3094: 77 02 00 00 20 00 00 00 r2 >>= 32
>>>>> 3095: b7 01 00 00 06 00 00 00 r1 = 6
>>>>> 3096: 15 02 02 00 01 00 00 00 if r2 == 1 goto +2 <LBB12_413>
>>>>> 3097: 18 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 r1 = 0
>>>>> ll
>>>>>
>>>>> 00000000000060d8 <LBB12_413>:
>>>>> ; return __encap_and_redirect_with_nodeid(ctx, tunnel->ip4,
>>>>> seclabel, monitor);
>>>>>
>>>>>
>>>>> b: BPF byte code after C code change:
>>>>>
>>>>> the C code diff change:
>>>>>
>>>>> diff --git a/bpf/lib/encap.h b/bpf/lib/encap.h
>>>>> index dfd87bd82..19199429d 100644
>>>>> --- a/bpf/lib/encap.h
>>>>> +++ b/bpf/lib/encap.h
>>>>> @@ -187,6 +187,8 @@ encap_and_redirect_lxc(struct __ctx_buff *ctx, __u32
>>>>> tunnel_endpoint,
>>>>> struct endpoint_key *key, __u32 seclabel, __u32
>>>>> monitor)
>>>>> {
>>>>> struct endpoint_key *tunnel;
>>>>> +#define VTEP_MAC { .addr = { 0xce, 0x72, 0xa7, 0x03, 0x88, 0x58 } }
>>>>> + union macaddr vtep_mac = VTEP_MAC;
>>>>> if (tunnel_endpoint) {
>>>>> #ifdef ENABLE_IPSEC
>>>>> @@ -221,6 +223,8 @@ encap_and_redirect_lxc(struct __ctx_buff *ctx, __u32
>>>>> tunnel_endpoint,
>>>>> seclabel);
>>>>> }
>>>>> #endif
>>>>> + if (eth_store_daddr(ctx, (__u8 *) &vtep_mac.addr, 0) < 0)
>>>>> + return DROP_WRITE_ERROR;
>>>>> return __encap_and_redirect_with_nodeid(ctx, tunnel->ip4,
>>>>> seclabel, monitor);
>>>>> }
>>>>>
>>>>> the result BPF byte code
>>>>>
>>>>> 0000000000004468 <LBB3_274>:
>>>>> 2189: bf a2 00 00 00 00 00 00 r2 = r10
>>>>> ; tunnel = map_lookup_elem(&TUNNEL_MAP, key);
>>>>> 2190: 07 02 00 00 50 ff ff ff r2 += -176
>>>>> 2191: 18 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 r1 = 0
>>>>> ll
>>>>> 2193: 85 00 00 00 01 00 00 00 call 1
>>>>> 2194: bf 07 00 00 00 00 00 00 r7 = r0
>>>>> 2195: 79 a6 48 ff 00 00 00 00 r6 = *(u64 *)(r10 - 184)
>>>>> ; if (!tunnel)
>>>>> 2196: 55 07 94 00 00 00 00 00 if r7 != 0 goto +148
>>>>> <LBB3_289>
>>>>>
>>>>> 00000000000044a8 <LBB3_275>:
>>>>> ; __u8 new_ttl, ttl = ip4->ttl;
>>>>> 2197: 79 a1 38 ff 00 00 00 00 r1 = *(u64 *)(r10 - 200)
>>>>> 2198: 71 13 16 00 00 00 00 00 r3 = *(u8 *)(r1 + 22)
>>>>> ; if (ttl <= 1)
>>>>> 2199: 25 03 01 00 01 00 00 00 if r3 > 1 goto +1 <LBB3_277>
>>>>> 2200: 05 00 20 ff 00 00 00 00 goto -224 <LBB3_253>
>>>>>
>>>>>
>>>>> You can see that:
>>>>>
>>>>> before change: <LBB12_410>
>>>>> after change <LBB3_274>
>>>>>
>>>>> is different that <LBB12_410> has instructions 3091, 3092... but
>>>>> <LBB3_274> end with instruction 2196
>>>>>
>>>>> before change: <LBB12_413> follows <LBB12_410>
>>>>> after change: <LBB3_275> follows <LBB3_274>
>>>>>
>>>>> <LBB12_413> and <LBB3_275> is very much different
>>>>>
>>>>> and <LBB3_275> instruction 2198 is the one with "R1 invalid mem access
>>>>> 'inv'"
>>>>>
>>>>> Why <LBB3_275> follows <LBB3_274> ? from C code, <LBB3_275> is not close
>>>>> to <LBB3_274>.
>>>>
>>>> The cilium code has a lot of functions inlined and after inlining, clang
>>>> may
>>>> do reordering based on its internal heuristics. It is totally possible
>>>> slight
>>>> code change may cause generated codes quite different.
>>>>
>>>> Regarding to
>>>>> and <LBB3_275> instruction 2198 is the one with "R1 invalid mem access
>>>>> 'inv'"
>>>>
>>>>
>>>>> 00000000000044a8 <LBB3_275>:
>>>>> ; __u8 new_ttl, ttl = ip4->ttl;
>>>>> 2197: 79 a1 38 ff 00 00 00 00 r1 = *(u64 *)(r10 - 200)
>>>>> 2198: 71 13 16 00 00 00 00 00 r3 = *(u8 *)(r1 + 22)
>>>>> ; if (ttl <= 1)
>>>>> 2199: 25 03 01 00 01 00 00 00 if r3 > 1 goto +1 <LBB3_277>
>>>>> 2200: 05 00 20 ff 00 00 00 00 goto -224 <LBB3_253>
>>>>
>>>> Looks like "ip4" is spilled on the stack. and maybe the stack save/restore
>>>> for
>>>> "ip4" does not preserve its original type.
>>>> This mostly happens to old kernels, I think.
>>>>
>>>
>>> the kernel 4.18 on Centos8, I also custom build most recent mainline git
>>> kernel 5.13 on Centos8, I recall I got same invaid memory access
>>>
>>>> If you have verifier log, it may help identify issues easily.
>>>
>>> Here is the complete verifer log, I skipped the BTF part
>>>
>>> level=warning msg="Prog section '2/7' rejected: Permission denied (13)!"
>>> subsys=datapath-loader
>>> level=warning msg=" - Type: 3" subsys=datapath-loader
>>> level=warning msg=" - Attach Type: 0" subsys=datapath-loader
>>> level=warning msg=" - Instructions: 2488 (0 over limit)"
>>> subsys=datapath-loader
>>> level=warning msg=" - License: GPL" subsys=datapath-loader
>>> level=warning subsys=datapath-loader
>>> level=warning msg="Verifier analysis:" subsys=datapath-loader
>>> level=warning subsys=datapath-loader
>>> level=warning msg="Skipped 158566 bytes, use 'verb' option for the full
>>> verbose log." subsys=datapath-loader
>>> level=warning msg="[...]" subsys=datapath-loader
>>> level=warning msg="-136=????00mm fp-144=00000000 fp-152=0000mmmm
>>> fp-160=????mmmm fp-168=mmmmmmmm fp-176=mmmmmmmm fp-184=ctx fp-192=mmmmmmmm
>>> fp-200=inv fp-208=mmmmmmmm fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm
>>> fp-240=inv128" subsys=datapath-loader
>>> level=warning msg="2437: (0f) r1 += r8" subsys=datapath-loader
>>> level=warning msg="2438: (7b) *(u64 *)(r0 +8) = r1" subsys=datapath-loader
>>> level=warning msg=" R0_w=map_value(id=0,off=0,ks=8,vs=16,imm=0)
>>> R1_w=inv(id=0) R6=ctx(id=0,off=0,imm=0)
>>> R7=inv(id=0,umax_value=128,var_off=(0x0; 0xff))
>>> R8=inv(id=0,umax_value=128,var_off=(0x0; 0xff)) R9=invP0 R10=fp0
>>> fp-8=mmmmmmmm fp-16=????mmmm fp-24=mmmmmmmm fp-32=mmmmmmmm fp-40=mmmmmmmm
>>> fp-48=mmmmmmmm fp-88=mmmmmmmm fp-96=00000000 fp-104=00000000
>>> fp-112=??mmmmmm fp-120=mmmmmmmm fp-128=??mmmmmm fp-136=????00mm
>>> fp-144=00000000 fp-152=0000mmmm fp-160=????mmmm fp-168=mmmmmmmm
>>> fp-176=mmmmmmmm fp-184=ctx fp-192=mmmmmmmm fp-200=inv fp-208=mmmmmmmm
>>> fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm fp-240=inv128"
>>> subsys=datapath-loader
>>> level=warning msg="2439: (05) goto pc+41" subsys=datapath-loader
>>> level=warning msg="2481: (18) r2 = 0x5c7" subsys=datapath-loader
>>> level=warning msg="2483: (67) r2 <<= 32" subsys=datapath-loader
>>> level=warning msg="2484: (77) r2 >>= 32" subsys=datapath-loader
>>> level=warning msg="2485: (b7) r1 = 6" subsys=datapath-loader
>>> level=warning msg="2486: (15) if r2 == 0x1 goto pc-341"
>>> subsys=datapath-loader
>>> level=warning msg="last_idx 2486 first_idx 2481" subsys=datapath-loader
>>> level=warning msg="regs=4 stack=0 before 2485: (b7) r1 = 6"
>>> subsys=datapath-loader
>>> level=warning msg="regs=4 stack=0 before 2484: (77) r2 >>= 32"
>>> subsys=datapath-loader
>>> level=warning msg="regs=4 stack=0 before 2483: (67) r2 <<= 32"
>>> subsys=datapath-loader
>>> level=warning msg="regs=4 stack=0 before 2481: (18) r2 = 0x5c7"
>>> subsys=datapath-loader
>>> level=warning msg="2487: (05) goto pc-344" subsys=datapath-loader
>>> level=warning msg="2144: (18) r1 = 0x5c7" subsys=datapath-loader
>>> level=warning msg="2146: (61) r2 = *(u32 *)(r6 +68)"
>>> subsys=datapath-loader
>>> level=warning msg="2147: (b7) r3 = 39" subsys=datapath-loader
>>> level=warning msg="2148: (63) *(u32 *)(r10 -76) = r3"
>>> subsys=datapath-loader
>>> level=warning msg="2149: (b7) r3 = 1" subsys=datapath-loader
>>> level=warning msg="2150: (6b) *(u16 *)(r10 -90) = r3"
>>> subsys=datapath-loader
>>> level=warning msg="2151: (63) *(u32 *)(r10 -96) = r8"
>>> subsys=datapath-loader
>>> level=warning msg="2152: (63) *(u32 *)(r10 -100) = r2"
>>> subsys=datapath-loader
>>> level=warning msg="2153: (18) r2 = 0x1d3" subsys=datapath-loader
>>> level=warning msg="2155: (6b) *(u16 *)(r10 -102) = r2"
>>> subsys=datapath-loader
>>> level=warning msg="2156: (b7) r2 = 1028" subsys=datapath-loader
>>> level=warning msg="2157: (6b) *(u16 *)(r10 -104) = r2"
>>> subsys=datapath-loader
>>> level=warning msg="2158: (b7) r2 = 0" subsys=datapath-loader
>>> level=warning msg="2159: (63) *(u32 *)(r10 -80) = r2"
>>> subsys=datapath-loader
>>> level=warning msg="last_idx 2159 first_idx 2481" subsys=datapath-loader
>>> level=warning msg="regs=4 stack=0 before 2158: (b7) r2 = 0"
>>> subsys=datapath-loader
>>> level=warning msg="2160: (63) *(u32 *)(r10 -84) = r2"
>>> subsys=datapath-loader
>>> level=warning msg="2161: (7b) *(u64 *)(r10 -72) = r2"
>>> subsys=datapath-loader
>>> level=warning msg="2162: (7b) *(u64 *)(r10 -64) = r2"
>>> subsys=datapath-loader
>>> level=warning msg="2163: (63) *(u32 *)(r10 -88) = r1"
>>> subsys=datapath-loader
>>> level=warning msg="2164: (6b) *(u16 *)(r10 -92) = r7"
>>> subsys=datapath-loader
>>> level=warning msg="2165: (67) r7 <<= 32" subsys=datapath-loader
>>> level=warning msg="2166: (18) r1 = 0xffffffff" subsys=datapath-loader
>>> level=warning msg="2168: (4f) r7 |= r1" subsys=datapath-loader
>>> level=warning msg="2169: (bf) r4 = r10" subsys=datapath-loader
>>> level=warning msg="2170: (07) r4 += -104" subsys=datapath-loader
>>> level=warning msg="2171: (bf) r1 = r6" subsys=datapath-loader
>>> level=warning msg="2172: (18) r2 = 0xffffa0c68cae1600"
>>> subsys=datapath-loader
>>> level=warning msg="2174: (bf) r3 = r7" subsys=datapath-loader
>>> level=warning msg="2175: (b7) r5 = 48" subsys=datapath-loader
>>> level=warning msg="2176: (85) call bpf_perf_event_output#25"
>>> subsys=datapath-loader
>>> level=warning msg="last_idx 2176 first_idx 2481" subsys=datapath-loader
>>> level=warning msg="regs=20 stack=0 before 2175: (b7) r5 = 48"
>>> subsys=datapath-loader
>>> level=warning msg="2177: (b7) r1 = 39" subsys=datapath-loader
>>> level=warning msg="2178: (b7) r2 = 0" subsys=datapath-loader
>>> level=warning msg="2179: (85) call bpf_redirect#23" subsys=datapath-loader
>>> level=warning msg="2180: (bf) r9 = r0" subsys=datapath-loader
>>> level=warning msg="2181: (bf) r1 = r9" subsys=datapath-loader
>>> level=warning msg="2182: (67) r1 <<= 32" subsys=datapath-loader
>>> level=warning msg="2183: (77) r1 >>= 32" subsys=datapath-loader
>>> level=warning msg="2184: (15) if r1 == 0x0 goto pc+57"
>>> subsys=datapath-loader
>>> level=warning msg=" R0_w=inv(id=0)
>>> R1_w=inv(id=0,umax_value=2147483647,var_off=(0x0; 0x7fffffff))
>>> R6=ctx(id=0,off=0,imm=0)
>>> R7=inv(id=0,umin_value=4294967295,umax_value=1099511627775,var_off=(0xffffffff;
>>> 0xff00000000),s32_min_value=-1,s32_max_value=0,u32_max_value=0)
>>> R8=inv(id=0,umax_value=128,var_off=(0x0; 0xff)) R9_w=inv(id=0) R10=fp0
>>> fp-8=mmmmmmmm fp-16=????mmmm fp-24=mmmmmmmm fp-32=mmmmmmmm fp-40=mmmmmmmm
>>> fp-48=mmmmmmmm fp-64=mmmmmmmm fp-72=mmmmmmmm fp-80=mmmmmmmm fp-88=mmmmmmmm
>>> fp-96=mmmmmmmm fp-104=mmmmmmmm fp-112=??mmmmmm fp-120=mmmmmmmm
>>> fp-128=??mmmmmm fp-136=????00mm fp-144=00000000 fp-152=0000mmmm
>>> fp-160=????mmmm fp-168=mmmmmmmm fp-176=mmmmmmmm fp-184=ctx fp-192=mmmmmmmm
>>> fp-200=inv fp-208=mmmmmmmm fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm
>>> fp-240=inv128" subsys=datapath-loader
>>> level=warning msg="2185: (18) r2 = 0xffffff60" subsys=datapath-loader
>>> level=warning msg="2187: (1d) if r1 == r2 goto pc+9"
>>> subsys=datapath-loader
>>> level=warning subsys=datapath-loader
>>> level=warning msg="from 2187 to 2197: R0=inv(id=0) R1=inv4294967136
>>> R2=inv4294967136 R6=ctx(id=0,off=0,imm=0)
>>> R7=inv(id=0,umin_value=4294967295,umax_value=1099511627775,var_off=(0xffffffff;
>>> 0xff00000000),s32_min_value=-1,s32_max_value=0,u32_max_value=0)
>>> R8=inv(id=0,umax_value=128,var_off=(0x0; 0xff)) R9=inv(id=0) R10=fp0
>>> fp-8=mmmmmmmm fp-16=????mmmm fp-24=mmmmmmmm fp-32=mmmmmmmm fp-40=mmmmmmmm
>>> fp-48=mmmmmmmm fp-64=mmmmmmmm fp-72=mmmmmmmm fp-80=mmmmmmmm fp-88=mmmmmmmm
>>> fp-96=mmmmmmmm fp-104=mmmmmmmm fp-112=??mmmmmm fp-120=mmmmmmmm
>>> fp-128=??mmmmmm fp-136=????00mm fp-144=00000000 fp-152=0000mmmm
>>> fp-160=????mmmm fp-168=mmmmmmmm fp-176=mmmmmmmm fp-184=ctx fp-192=mmmmmmmm
>>> fp-200=inv fp-208=mmmmmmmm fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm
>>
>> This is the problem. Here, we have "fp-200=inv" and
>> later on we have
>> r1 = *(u64 *)(r10 -200) // r1 is a unknown scalar
>>
>> We cannot do the following operation
>> r3 = *(u8 *)(r1 +22)
>> since r1 is a unknown scalar and the verifier rightfully rejected
>> the program.
>>
>> You need to examine complete log to find out why fp-200 stores
>> an "inv" (a unknown scalar).
>
> I guess you mean the complete log starting from the prog section 2/7 from
> verifier, if so, it seems fp-200 started with "inv"
>
> level=warning msg="Prog section '2/7' rejected: Permission denied (13)!"
> subsys=datapath-loader
>
> level=warning msg="-136=????00mm fp-144=00000000 fp-152=0000mmmm
> fp-160=????mmmm fp-168=mmmmmmmm fp-176=mmmmmmmm fp-184=ctx fp-192=mmmmmmmm
> fp-200=inv fp-208=mmmmmmmm fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm
> fp-240=inv128" subsys=datapath-loader
>
> and I don't see fp-200 ever changed to something else after, maybe I am
> reading it wrong
The log is truncated.
>>> level=warning msg="[...]" subsys=datapath-loader
>>> level=warning msg="-136=????00mm fp-144=00000000 fp-152=0000mmmm
>>> fp-160=????mmmm fp-168=mmmmmmmm fp-176=mmmmmmmm fp-184=ctx
fp-192=mmmmmmmm
>>> fp-200=inv fp-208=mmmmmmmm fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm
>>> fp-240=inv128" subsys=datapath-loader
>>> level=warning msg="2437: (0f) r1 += r8" subsys=datapath-loader
>>> level=warning msg="2438: (7b) *(u64 *)(r0 +8) = r1"
subsys=datapath-loader
The log starts with insn 2437.
The complete log should start with insn 0.
>
>>
>>> fp-240=inv128" subsys=datapath-loader
>>> level=warning msg="2197: (79) r1 = *(u64 *)(r10 -200)"
>>> subsys=datapath-loader
>>> level=warning msg="2198: (71) r3 = *(u8 *)(r1 +22)" subsys=datapath-loader
>>> level=warning msg="R1 invalid mem access 'inv'" subsys=datapath-loader
>>> level=warning msg="processed 1802 insns (limit 1000000)
>>> max_states_per_insn 4 total_states 103 peak_states 103 mark_read 49"
>>> subsys=datapath-loader
>>> level=warning subsys=datapath-loader
>>> level=warning msg="Error filling program arrays!" subsys=datapath-loader
>>> level=warning msg="Unable to load program" subsys=datapath-loader
>>>
>>>
>>>
>>>>>
>>>>>
>>>>> 2, Can I assume the verifier is to simulate the order of BPF byte
>>>>> code execution in run time, like if without any jump or goto in
>>>>> <LBB3_274>, <LBB3_275> will be executed after <LBB3_274>?
>>>>
>>>> The verifier will try to verify both paths, jumping to LBB3_289
>>>> or fall back to LBB3_275.
>>>>
>>>>>
>>>>>
>>>>>
>>>>> Enterprise Network Engineer
>>>>> F5 Networks Inc
>>>>> https://www.youtube.com/c/VincentLi
>>>>>
>>>>
>>
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: R1 invalid mem access 'inv'
2021-06-18 0:51 ` Yonghong Song
@ 2021-06-18 3:58 ` Vincent Li
2021-06-18 4:15 ` Vincent Li
0 siblings, 1 reply; 12+ messages in thread
From: Vincent Li @ 2021-06-18 3:58 UTC (permalink / raw)
To: Yonghong Song; +Cc: Vincent Li, bpf
On Thu, 17 Jun 2021, Yonghong Song wrote:
>
>
> On 6/17/21 3:19 PM, Vincent Li wrote:
> >
> >
> > On Thu, 17 Jun 2021, Yonghong Song wrote:
> >
> > >
> > >
> > > On 6/17/21 7:19 AM, Vincent Li wrote:
> > > >
> > > > Hi Song,
> > > >
> > > > Thank you for your response!
> > > >
> > > >
> > > > On Wed, 16 Jun 2021, Yonghong Song wrote:
> > > >
> > > > >
> > > > >
> > > > > On 6/16/21 5:05 PM, Vincent Li wrote:
> > > > > > Hi BPF Experts,
> > > > > >
> > > > > > I had a problem that verifier report "R1 invalid mem access 'inv'"
> > > > > > when
> > > > > > I attempted to rewrite packet destination ethernet MAC address in
> > > > > > Cilium
> > > > > > tunnel mode, I opened an issue
> > > > > > with detail here https://github.com/cilium/cilium/issues/16571:
> > > > > >
> > > > > > I have couple of questions in general to try to understand the
> > > > > > compiler,
> > > > > > BPF byte code, and the verifier.
> > > > > >
> > > > > > 1 Why the BPF byte code changes so much with my simple C code change
> > > > > >
> > > > > > a: BPF byte code before C code change:
> > > > > >
> > > > > > 0000000000006068 <LBB12_410>:
> > > > > > 3085: bf a2 00 00 00 00 00 00 r2 = r10
> > > > > > ; tunnel = map_lookup_elem(&TUNNEL_MAP, key);
> > > > > > 3086: 07 02 00 00 78 ff ff ff r2 += -136
> > > > > > 3087: 18 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00
> > > > > > r1 = 0
> > > > > > ll
> > > > > > 3089: 85 00 00 00 01 00 00 00 call 1
> > > > > > ; if (!tunnel)
> > > > > > 3090: 15 00 06 01 00 00 00 00 if r0 == 0 goto +262
> > > > > > <LBB12_441>
> > > > > > ; key.tunnel_id = seclabel;
> > > > > > 3091: 18 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00
> > > > > > r2 = 0
> > > > > > ll
> > > > > > 3093: 67 02 00 00 20 00 00 00 r2 <<= 32
> > > > > > 3094: 77 02 00 00 20 00 00 00 r2 >>= 32
> > > > > > 3095: b7 01 00 00 06 00 00 00 r1 = 6
> > > > > > 3096: 15 02 02 00 01 00 00 00 if r2 == 1 goto +2
> > > > > > <LBB12_413>
> > > > > > 3097: 18 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00
> > > > > > r1 = 0
> > > > > > ll
> > > > > >
> > > > > > 00000000000060d8 <LBB12_413>:
> > > > > > ; return __encap_and_redirect_with_nodeid(ctx, tunnel->ip4,
> > > > > > seclabel, monitor);
> > > > > >
> > > > > >
> > > > > > b: BPF byte code after C code change:
> > > > > >
> > > > > > the C code diff change:
> > > > > >
> > > > > > diff --git a/bpf/lib/encap.h b/bpf/lib/encap.h
> > > > > > index dfd87bd82..19199429d 100644
> > > > > > --- a/bpf/lib/encap.h
> > > > > > +++ b/bpf/lib/encap.h
> > > > > > @@ -187,6 +187,8 @@ encap_and_redirect_lxc(struct __ctx_buff *ctx,
> > > > > > __u32
> > > > > > tunnel_endpoint,
> > > > > > struct endpoint_key *key, __u32 seclabel,
> > > > > > __u32
> > > > > > monitor)
> > > > > > {
> > > > > > struct endpoint_key *tunnel;
> > > > > > +#define VTEP_MAC { .addr = { 0xce, 0x72, 0xa7, 0x03, 0x88, 0x58 }
> > > > > > }
> > > > > > + union macaddr vtep_mac = VTEP_MAC;
> > > > > > if (tunnel_endpoint) {
> > > > > > #ifdef ENABLE_IPSEC
> > > > > > @@ -221,6 +223,8 @@ encap_and_redirect_lxc(struct __ctx_buff *ctx,
> > > > > > __u32
> > > > > > tunnel_endpoint,
> > > > > > seclabel);
> > > > > > }
> > > > > > #endif
> > > > > > + if (eth_store_daddr(ctx, (__u8 *) &vtep_mac.addr, 0) < 0)
> > > > > > + return DROP_WRITE_ERROR;
> > > > > > return __encap_and_redirect_with_nodeid(ctx, tunnel->ip4,
> > > > > > seclabel, monitor);
> > > > > > }
> > > > > >
> > > > > > the result BPF byte code
> > > > > >
> > > > > > 0000000000004468 <LBB3_274>:
> > > > > > 2189: bf a2 00 00 00 00 00 00 r2 = r10
> > > > > > ; tunnel = map_lookup_elem(&TUNNEL_MAP, key);
> > > > > > 2190: 07 02 00 00 50 ff ff ff r2 += -176
> > > > > > 2191: 18 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00
> > > > > > r1 = 0
> > > > > > ll
> > > > > > 2193: 85 00 00 00 01 00 00 00 call 1
> > > > > > 2194: bf 07 00 00 00 00 00 00 r7 = r0
> > > > > > 2195: 79 a6 48 ff 00 00 00 00 r6 = *(u64 *)(r10 - 184)
> > > > > > ; if (!tunnel)
> > > > > > 2196: 55 07 94 00 00 00 00 00 if r7 != 0 goto +148
> > > > > > <LBB3_289>
> > > > > >
> > > > > > 00000000000044a8 <LBB3_275>:
> > > > > > ; __u8 new_ttl, ttl = ip4->ttl;
> > > > > > 2197: 79 a1 38 ff 00 00 00 00 r1 = *(u64 *)(r10 - 200)
> > > > > > 2198: 71 13 16 00 00 00 00 00 r3 = *(u8 *)(r1 + 22)
> > > > > > ; if (ttl <= 1)
> > > > > > 2199: 25 03 01 00 01 00 00 00 if r3 > 1 goto +1
> > > > > > <LBB3_277>
> > > > > > 2200: 05 00 20 ff 00 00 00 00 goto -224 <LBB3_253>
> > > > > >
> > > > > >
> > > > > > You can see that:
> > > > > >
> > > > > > before change: <LBB12_410>
> > > > > > after change <LBB3_274>
> > > > > >
> > > > > > is different that <LBB12_410> has instructions 3091, 3092... but
> > > > > > <LBB3_274> end with instruction 2196
> > > > > >
> > > > > > before change: <LBB12_413> follows <LBB12_410>
> > > > > > after change: <LBB3_275> follows <LBB3_274>
> > > > > >
> > > > > > <LBB12_413> and <LBB3_275> is very much different
> > > > > >
> > > > > > and <LBB3_275> instruction 2198 is the one with "R1 invalid mem
> > > > > > access
> > > > > > 'inv'"
> > > > > >
> > > > > > Why <LBB3_275> follows <LBB3_274> ? from C code, <LBB3_275> is not
> > > > > > close
> > > > > > to <LBB3_274>.
> > > > >
> > > > > The cilium code has a lot of functions inlined and after inlining,
> > > > > clang
> > > > > may
> > > > > do reordering based on its internal heuristics. It is totally possible
> > > > > slight
> > > > > code change may cause generated codes quite different.
> > > > >
> > > > > Regarding to
> > > > > > and <LBB3_275> instruction 2198 is the one with "R1 invalid mem
> > > > > > access
> > > > > > 'inv'"
> > > > >
> > > > >
> > > > > > 00000000000044a8 <LBB3_275>:
> > > > > > ; __u8 new_ttl, ttl = ip4->ttl;
> > > > > > 2197: 79 a1 38 ff 00 00 00 00 r1 = *(u64 *)(r10 - 200)
> > > > > > 2198: 71 13 16 00 00 00 00 00 r3 = *(u8 *)(r1 + 22)
> > > > > > ; if (ttl <= 1)
> > > > > > 2199: 25 03 01 00 01 00 00 00 if r3 > 1 goto +1
> > > > > > <LBB3_277>
> > > > > > 2200: 05 00 20 ff 00 00 00 00 goto -224 <LBB3_253>
> > > > >
> > > > > Looks like "ip4" is spilled on the stack. and maybe the stack
> > > > > save/restore
> > > > > for
> > > > > "ip4" does not preserve its original type.
> > > > > This mostly happens to old kernels, I think.
> > > > >
> > > >
> > > > the kernel 4.18 on Centos8, I also custom build most recent mainline git
> > > > kernel 5.13 on Centos8, I recall I got same invaid memory access
> > > >
> > > > > If you have verifier log, it may help identify issues easily.
> > > >
> > > > Here is the complete verifer log, I skipped the BTF part
> > > >
> > > > level=warning msg="Prog section '2/7' rejected: Permission denied (13)!"
> > > > subsys=datapath-loader
> > > > level=warning msg=" - Type: 3" subsys=datapath-loader
> > > > level=warning msg=" - Attach Type: 0" subsys=datapath-loader
> > > > level=warning msg=" - Instructions: 2488 (0 over limit)"
> > > > subsys=datapath-loader
> > > > level=warning msg=" - License: GPL" subsys=datapath-loader
> > > > level=warning subsys=datapath-loader
> > > > level=warning msg="Verifier analysis:" subsys=datapath-loader
> > > > level=warning subsys=datapath-loader
> > > > level=warning msg="Skipped 158566 bytes, use 'verb' option for the full
> > > > verbose log." subsys=datapath-loader
> > > > level=warning msg="[...]" subsys=datapath-loader
> > > > level=warning msg="-136=????00mm fp-144=00000000 fp-152=0000mmmm
> > > > fp-160=????mmmm fp-168=mmmmmmmm fp-176=mmmmmmmm fp-184=ctx
> > > > fp-192=mmmmmmmm
> > > > fp-200=inv fp-208=mmmmmmmm fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm
> > > > fp-240=inv128" subsys=datapath-loader
> > > > level=warning msg="2437: (0f) r1 += r8" subsys=datapath-loader
> > > > level=warning msg="2438: (7b) *(u64 *)(r0 +8) = r1"
> > > > subsys=datapath-loader
> > > > level=warning msg=" R0_w=map_value(id=0,off=0,ks=8,vs=16,imm=0)
> > > > R1_w=inv(id=0) R6=ctx(id=0,off=0,imm=0)
> > > > R7=inv(id=0,umax_value=128,var_off=(0x0; 0xff))
> > > > R8=inv(id=0,umax_value=128,var_off=(0x0; 0xff)) R9=invP0 R10=fp0
> > > > fp-8=mmmmmmmm fp-16=????mmmm fp-24=mmmmmmmm fp-32=mmmmmmmm
> > > > fp-40=mmmmmmmm
> > > > fp-48=mmmmmmmm fp-88=mmmmmmmm fp-96=00000000 fp-104=00000000
> > > > fp-112=??mmmmmm fp-120=mmmmmmmm fp-128=??mmmmmm fp-136=????00mm
> > > > fp-144=00000000 fp-152=0000mmmm fp-160=????mmmm fp-168=mmmmmmmm
> > > > fp-176=mmmmmmmm fp-184=ctx fp-192=mmmmmmmm fp-200=inv fp-208=mmmmmmmm
> > > > fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm fp-240=inv128"
> > > > subsys=datapath-loader
> > > > level=warning msg="2439: (05) goto pc+41" subsys=datapath-loader
> > > > level=warning msg="2481: (18) r2 = 0x5c7" subsys=datapath-loader
> > > > level=warning msg="2483: (67) r2 <<= 32" subsys=datapath-loader
> > > > level=warning msg="2484: (77) r2 >>= 32" subsys=datapath-loader
> > > > level=warning msg="2485: (b7) r1 = 6" subsys=datapath-loader
> > > > level=warning msg="2486: (15) if r2 == 0x1 goto pc-341"
> > > > subsys=datapath-loader
> > > > level=warning msg="last_idx 2486 first_idx 2481" subsys=datapath-loader
> > > > level=warning msg="regs=4 stack=0 before 2485: (b7) r1 = 6"
> > > > subsys=datapath-loader
> > > > level=warning msg="regs=4 stack=0 before 2484: (77) r2 >>= 32"
> > > > subsys=datapath-loader
> > > > level=warning msg="regs=4 stack=0 before 2483: (67) r2 <<= 32"
> > > > subsys=datapath-loader
> > > > level=warning msg="regs=4 stack=0 before 2481: (18) r2 = 0x5c7"
> > > > subsys=datapath-loader
> > > > level=warning msg="2487: (05) goto pc-344" subsys=datapath-loader
> > > > level=warning msg="2144: (18) r1 = 0x5c7" subsys=datapath-loader
> > > > level=warning msg="2146: (61) r2 = *(u32 *)(r6 +68)"
> > > > subsys=datapath-loader
> > > > level=warning msg="2147: (b7) r3 = 39" subsys=datapath-loader
> > > > level=warning msg="2148: (63) *(u32 *)(r10 -76) = r3"
> > > > subsys=datapath-loader
> > > > level=warning msg="2149: (b7) r3 = 1" subsys=datapath-loader
> > > > level=warning msg="2150: (6b) *(u16 *)(r10 -90) = r3"
> > > > subsys=datapath-loader
> > > > level=warning msg="2151: (63) *(u32 *)(r10 -96) = r8"
> > > > subsys=datapath-loader
> > > > level=warning msg="2152: (63) *(u32 *)(r10 -100) = r2"
> > > > subsys=datapath-loader
> > > > level=warning msg="2153: (18) r2 = 0x1d3" subsys=datapath-loader
> > > > level=warning msg="2155: (6b) *(u16 *)(r10 -102) = r2"
> > > > subsys=datapath-loader
> > > > level=warning msg="2156: (b7) r2 = 1028" subsys=datapath-loader
> > > > level=warning msg="2157: (6b) *(u16 *)(r10 -104) = r2"
> > > > subsys=datapath-loader
> > > > level=warning msg="2158: (b7) r2 = 0" subsys=datapath-loader
> > > > level=warning msg="2159: (63) *(u32 *)(r10 -80) = r2"
> > > > subsys=datapath-loader
> > > > level=warning msg="last_idx 2159 first_idx 2481" subsys=datapath-loader
> > > > level=warning msg="regs=4 stack=0 before 2158: (b7) r2 = 0"
> > > > subsys=datapath-loader
> > > > level=warning msg="2160: (63) *(u32 *)(r10 -84) = r2"
> > > > subsys=datapath-loader
> > > > level=warning msg="2161: (7b) *(u64 *)(r10 -72) = r2"
> > > > subsys=datapath-loader
> > > > level=warning msg="2162: (7b) *(u64 *)(r10 -64) = r2"
> > > > subsys=datapath-loader
> > > > level=warning msg="2163: (63) *(u32 *)(r10 -88) = r1"
> > > > subsys=datapath-loader
> > > > level=warning msg="2164: (6b) *(u16 *)(r10 -92) = r7"
> > > > subsys=datapath-loader
> > > > level=warning msg="2165: (67) r7 <<= 32" subsys=datapath-loader
> > > > level=warning msg="2166: (18) r1 = 0xffffffff" subsys=datapath-loader
> > > > level=warning msg="2168: (4f) r7 |= r1" subsys=datapath-loader
> > > > level=warning msg="2169: (bf) r4 = r10" subsys=datapath-loader
> > > > level=warning msg="2170: (07) r4 += -104" subsys=datapath-loader
> > > > level=warning msg="2171: (bf) r1 = r6" subsys=datapath-loader
> > > > level=warning msg="2172: (18) r2 = 0xffffa0c68cae1600"
> > > > subsys=datapath-loader
> > > > level=warning msg="2174: (bf) r3 = r7" subsys=datapath-loader
> > > > level=warning msg="2175: (b7) r5 = 48" subsys=datapath-loader
> > > > level=warning msg="2176: (85) call bpf_perf_event_output#25"
> > > > subsys=datapath-loader
> > > > level=warning msg="last_idx 2176 first_idx 2481" subsys=datapath-loader
> > > > level=warning msg="regs=20 stack=0 before 2175: (b7) r5 = 48"
> > > > subsys=datapath-loader
> > > > level=warning msg="2177: (b7) r1 = 39" subsys=datapath-loader
> > > > level=warning msg="2178: (b7) r2 = 0" subsys=datapath-loader
> > > > level=warning msg="2179: (85) call bpf_redirect#23"
> > > > subsys=datapath-loader
> > > > level=warning msg="2180: (bf) r9 = r0" subsys=datapath-loader
> > > > level=warning msg="2181: (bf) r1 = r9" subsys=datapath-loader
> > > > level=warning msg="2182: (67) r1 <<= 32" subsys=datapath-loader
> > > > level=warning msg="2183: (77) r1 >>= 32" subsys=datapath-loader
> > > > level=warning msg="2184: (15) if r1 == 0x0 goto pc+57"
> > > > subsys=datapath-loader
> > > > level=warning msg=" R0_w=inv(id=0)
> > > > R1_w=inv(id=0,umax_value=2147483647,var_off=(0x0; 0x7fffffff))
> > > > R6=ctx(id=0,off=0,imm=0)
> > > > R7=inv(id=0,umin_value=4294967295,umax_value=1099511627775,var_off=(0xffffffff;
> > > > 0xff00000000),s32_min_value=-1,s32_max_value=0,u32_max_value=0)
> > > > R8=inv(id=0,umax_value=128,var_off=(0x0; 0xff)) R9_w=inv(id=0) R10=fp0
> > > > fp-8=mmmmmmmm fp-16=????mmmm fp-24=mmmmmmmm fp-32=mmmmmmmm
> > > > fp-40=mmmmmmmm
> > > > fp-48=mmmmmmmm fp-64=mmmmmmmm fp-72=mmmmmmmm fp-80=mmmmmmmm
> > > > fp-88=mmmmmmmm
> > > > fp-96=mmmmmmmm fp-104=mmmmmmmm fp-112=??mmmmmm fp-120=mmmmmmmm
> > > > fp-128=??mmmmmm fp-136=????00mm fp-144=00000000 fp-152=0000mmmm
> > > > fp-160=????mmmm fp-168=mmmmmmmm fp-176=mmmmmmmm fp-184=ctx
> > > > fp-192=mmmmmmmm
> > > > fp-200=inv fp-208=mmmmmmmm fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm
> > > > fp-240=inv128" subsys=datapath-loader
> > > > level=warning msg="2185: (18) r2 = 0xffffff60" subsys=datapath-loader
> > > > level=warning msg="2187: (1d) if r1 == r2 goto pc+9"
> > > > subsys=datapath-loader
> > > > level=warning subsys=datapath-loader
> > > > level=warning msg="from 2187 to 2197: R0=inv(id=0) R1=inv4294967136
> > > > R2=inv4294967136 R6=ctx(id=0,off=0,imm=0)
> > > > R7=inv(id=0,umin_value=4294967295,umax_value=1099511627775,var_off=(0xffffffff;
> > > > 0xff00000000),s32_min_value=-1,s32_max_value=0,u32_max_value=0)
> > > > R8=inv(id=0,umax_value=128,var_off=(0x0; 0xff)) R9=inv(id=0) R10=fp0
> > > > fp-8=mmmmmmmm fp-16=????mmmm fp-24=mmmmmmmm fp-32=mmmmmmmm
> > > > fp-40=mmmmmmmm
> > > > fp-48=mmmmmmmm fp-64=mmmmmmmm fp-72=mmmmmmmm fp-80=mmmmmmmm
> > > > fp-88=mmmmmmmm
> > > > fp-96=mmmmmmmm fp-104=mmmmmmmm fp-112=??mmmmmm fp-120=mmmmmmmm
> > > > fp-128=??mmmmmm fp-136=????00mm fp-144=00000000 fp-152=0000mmmm
> > > > fp-160=????mmmm fp-168=mmmmmmmm fp-176=mmmmmmmm fp-184=ctx
> > > > fp-192=mmmmmmmm
> > > > fp-200=inv fp-208=mmmmmmmm fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm
> > >
> > > This is the problem. Here, we have "fp-200=inv" and
> > > later on we have
> > > r1 = *(u64 *)(r10 -200) // r1 is a unknown scalar
> > >
> > > We cannot do the following operation
> > > r3 = *(u8 *)(r1 +22)
> > > since r1 is a unknown scalar and the verifier rightfully rejected
> > > the program.
> > >
> > > You need to examine complete log to find out why fp-200 stores
> > > an "inv" (a unknown scalar).
> >
> > I guess you mean the complete log starting from the prog section 2/7 from
> > verifier, if so, it seems fp-200 started with "inv"
> >
> > level=warning msg="Prog section '2/7' rejected: Permission denied (13)!"
> > subsys=datapath-loader
> >
> > level=warning msg="-136=????00mm fp-144=00000000 fp-152=0000mmmm
> > fp-160=????mmmm fp-168=mmmmmmmm fp-176=mmmmmmmm fp-184=ctx fp-192=mmmmmmmm
> > fp-200=inv fp-208=mmmmmmmm fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm
> > fp-240=inv128" subsys=datapath-loader
> >
> > and I don't see fp-200 ever changed to something else after, maybe I am
> > reading it wrong
>
> The log is truncated.
>
> >>> level=warning msg="[...]" subsys=datapath-loader
> >>> level=warning msg="-136=????00mm fp-144=00000000 fp-152=0000mmmm
> >>> fp-160=????mmmm fp-168=mmmmmmmm fp-176=mmmmmmmm fp-184=ctx fp-192=mmmmmmmm
> >>> fp-200=inv fp-208=mmmmmmmm fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm
> >>> fp-240=inv128" subsys=datapath-loader
> >>> level=warning msg="2437: (0f) r1 += r8" subsys=datapath-loader
> >>> level=warning msg="2438: (7b) *(u64 *)(r0 +8) = r1" subsys=datapath-loader
>
> The log starts with insn 2437.
> The complete log should start with insn 0.
I see, it looks verb option need to be appended to the tc command I guess
I will check with Cilium experts on appending the verb to the tc command
level=error msg="Command execution failed" cmd="[tc filter replace dev
lxc10a7b9a3c745 ingress prio 1 handle 1 bpf da obj 467_next/bpf_lxc.o sec
from-container]" error="exit status 1" subsys=datapath-loader
level=warning subsys=datapath-loader
level=warning msg="BTF debug data section '.BTF' rejected: Invalid
argument (22)!" subsys=datapath-loader
level=warning msg=" - Length: 24779" subsys=datapath-loader
level=warning msg="Verifier analysis:" subsys=datapath-loader
level=warning subsys=datapath-loader
level=warning msg="Skipped 787 bytes, use 'verb' option for the full
verbose log." subsys=datapath-loader
>
> >
> > >
> > > > fp-240=inv128" subsys=datapath-loader
> > > > level=warning msg="2197: (79) r1 = *(u64 *)(r10 -200)"
> > > > subsys=datapath-loader
> > > > level=warning msg="2198: (71) r3 = *(u8 *)(r1 +22)"
> > > > subsys=datapath-loader
> > > > level=warning msg="R1 invalid mem access 'inv'" subsys=datapath-loader
> > > > level=warning msg="processed 1802 insns (limit 1000000)
> > > > max_states_per_insn 4 total_states 103 peak_states 103 mark_read 49"
> > > > subsys=datapath-loader
> > > > level=warning subsys=datapath-loader
> > > > level=warning msg="Error filling program arrays!" subsys=datapath-loader
> > > > level=warning msg="Unable to load program" subsys=datapath-loader
> > > >
> > > >
> > > > > >
> > > > > >
> > > > > > 2, Can I assume the verifier is to simulate the order of BPF byte
> > > > > > code execution in run time, like if without any jump or goto in
> > > > > > <LBB3_274>, <LBB3_275> will be executed after <LBB3_274>?
> > > > >
> > > > > The verifier will try to verify both paths, jumping to LBB3_289
> > > > > or fall back to LBB3_275.
> > > > >
> > > > > >
> > > > > >
> > > > > >
> > > > > > Enterprise Network Engineer
> > > > > > F5 Networks Inc
> > > > > > https://www.youtube.com/c/VincentLi
> > > > > >
> > > > >
> > >
>
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: R1 invalid mem access 'inv'
2021-06-18 3:58 ` Vincent Li
@ 2021-06-18 4:15 ` Vincent Li
[not found] ` <CAK3+h2xv-EZH9afEymGqKdwHozHHu=XHJYKispFSixYxz7YVLQ@mail.gmail.com>
0 siblings, 1 reply; 12+ messages in thread
From: Vincent Li @ 2021-06-18 4:15 UTC (permalink / raw)
To: Vincent Li; +Cc: Yonghong Song, bpf
On Thu, 17 Jun 2021, Vincent Li wrote:
>
>
> On Thu, 17 Jun 2021, Yonghong Song wrote:
>
> >
> >
> > On 6/17/21 3:19 PM, Vincent Li wrote:
> > >
> > >
> > > On Thu, 17 Jun 2021, Yonghong Song wrote:
> > >
> > > >
> > > >
> > > > On 6/17/21 7:19 AM, Vincent Li wrote:
> > > > >
> > > > > Hi Song,
> > > > >
> > > > > Thank you for your response!
> > > > >
> > > > >
> > > > > On Wed, 16 Jun 2021, Yonghong Song wrote:
> > > > >
> > > > > >
> > > > > >
> > > > > > On 6/16/21 5:05 PM, Vincent Li wrote:
> > > > > > > Hi BPF Experts,
> > > > > > >
> > > > > > > I had a problem that verifier report "R1 invalid mem access 'inv'"
> > > > > > > when
> > > > > > > I attempted to rewrite packet destination ethernet MAC
address in
> > > > > > > Cilium
> > > > > > > tunnel mode, I opened an issue
> > > > > > > with detail here https://github.com/cilium/cilium/issues/16571:
> > > > > > >
> > > > > > > I have couple of questions in general to try to understand the
> > > > > > > compiler,
> > > > > > > BPF byte code, and the verifier.
> > > > > > >
> > > > > > > 1 Why the BPF byte code changes so much with my simple C code change
> > > > > > >
> > > > > > > a: BPF byte code before C code change:
> > > > > > >
> > > > > > > 0000000000006068 <LBB12_410>:
> > > > > > > 3085: bf a2 00 00 00 00 00 00 r2 = r10
> > > > > > > ; tunnel = map_lookup_elem(&TUNNEL_MAP, key);
> > > > > > > 3086: 07 02 00 00 78 ff ff ff r2 += -136
> > > > > > > 3087: 18 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00
> > > > > > > r1 = 0
> > > > > > > ll
> > > > > > > 3089: 85 00 00 00 01 00 00 00 call 1
> > > > > > > ; if (!tunnel)
> > > > > > > 3090: 15 00 06 01 00 00 00 00 if r0 == 0 goto +262
> > > > > > > <LBB12_441>
> > > > > > > ; key.tunnel_id = seclabel;
> > > > > > > 3091: 18 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00
> > > > > > > r2 = 0
> > > > > > > ll
> > > > > > > 3093: 67 02 00 00 20 00 00 00 r2 <<= 32
> > > > > > > 3094: 77 02 00 00 20 00 00 00 r2 >>= 32
> > > > > > > 3095: b7 01 00 00 06 00 00 00 r1 = 6
> > > > > > > 3096: 15 02 02 00 01 00 00 00 if r2 == 1 goto +2
> > > > > > > <LBB12_413>
> > > > > > > 3097: 18 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00
> > > > > > > r1 = 0
> > > > > > > ll
> > > > > > >
> > > > > > > 00000000000060d8 <LBB12_413>:
> > > > > > > ; return __encap_and_redirect_with_nodeid(ctx, tunnel->ip4,
> > > > > > > seclabel, monitor);
> > > > > > >
> > > > > > >
> > > > > > > b: BPF byte code after C code change:
> > > > > > >
> > > > > > > the C code diff change:
> > > > > > >
> > > > > > > diff --git a/bpf/lib/encap.h b/bpf/lib/encap.h
> > > > > > > index dfd87bd82..19199429d 100644
> > > > > > > --- a/bpf/lib/encap.h
> > > > > > > +++ b/bpf/lib/encap.h
> > > > > > > @@ -187,6 +187,8 @@ encap_and_redirect_lxc(struct __ctx_buff *ctx,
> > > > > > > __u32
> > > > > > > tunnel_endpoint,
> > > > > > > struct endpoint_key *key, __u32 seclabel,
> > > > > > > __u32
> > > > > > > monitor)
> > > > > > > {
> > > > > > > struct endpoint_key *tunnel;
> > > > > > > +#define VTEP_MAC { .addr = { 0xce, 0x72, 0xa7, 0x03, 0x88, 0x58 }
> > > > > > > }
> > > > > > > + union macaddr vtep_mac = VTEP_MAC;
> > > > > > > if (tunnel_endpoint) {
> > > > > > > #ifdef ENABLE_IPSEC
> > > > > > > @@ -221,6 +223,8 @@ encap_and_redirect_lxc(struct __ctx_buff *ctx,
> > > > > > > __u32
> > > > > > > tunnel_endpoint,
> > > > > > > seclabel);
> > > > > > > }
> > > > > > > #endif
> > > > > > > + if (eth_store_daddr(ctx, (__u8 *) &vtep_mac.addr, 0) < 0)
> > > > > > > + return DROP_WRITE_ERROR;
> > > > > > > return __encap_and_redirect_with_nodeid(ctx, tunnel->ip4,
> > > > > > > seclabel, monitor);
> > > > > > > }
> > > > > > >
> > > > > > > the result BPF byte code
> > > > > > >
> > > > > > > 0000000000004468 <LBB3_274>:
> > > > > > > 2189: bf a2 00 00 00 00 00 00 r2 = r10
> > > > > > > ; tunnel = map_lookup_elem(&TUNNEL_MAP, key);
> > > > > > > 2190: 07 02 00 00 50 ff ff ff r2 += -176
> > > > > > > 2191: 18 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00
> > > > > > > r1 = 0
> > > > > > > ll
> > > > > > > 2193: 85 00 00 00 01 00 00 00 call 1
> > > > > > > 2194: bf 07 00 00 00 00 00 00 r7 = r0
> > > > > > > 2195: 79 a6 48 ff 00 00 00 00 r6 = *(u64 *)(r10 - 184)
> > > > > > > ; if (!tunnel)
> > > > > > > 2196: 55 07 94 00 00 00 00 00 if r7 != 0 goto +148
> > > > > > > <LBB3_289>
> > > > > > >
> > > > > > > 00000000000044a8 <LBB3_275>:
> > > > > > > ; __u8 new_ttl, ttl = ip4->ttl;
> > > > > > > 2197: 79 a1 38 ff 00 00 00 00 r1 = *(u64 *)(r10 - 200)
> > > > > > > 2198: 71 13 16 00 00 00 00 00 r3 = *(u8 *)(r1 + 22)
> > > > > > > ; if (ttl <= 1)
> > > > > > > 2199: 25 03 01 00 01 00 00 00 if r3 > 1 goto +1
> > > > > > > <LBB3_277>
> > > > > > > 2200: 05 00 20 ff 00 00 00 00 goto -224 <LBB3_253>
> > > > > > >
> > > > > > >
> > > > > > > You can see that:
> > > > > > >
> > > > > > > before change: <LBB12_410>
> > > > > > > after change <LBB3_274>
> > > > > > >
> > > > > > > is different that <LBB12_410> has instructions 3091, 3092... but
> > > > > > > <LBB3_274> end with instruction 2196
> > > > > > >
> > > > > > > before change: <LBB12_413> follows <LBB12_410>
> > > > > > > after change: <LBB3_275> follows <LBB3_274>
> > > > > > >
> > > > > > > <LBB12_413> and <LBB3_275> is very much different
> > > > > > >
> > > > > > > and <LBB3_275> instruction 2198 is the one with "R1 invalid mem
> > > > > > > access
> > > > > > > 'inv'"
> > > > > > >
> > > > > > > Why <LBB3_275> follows <LBB3_274> ? from C code, <LBB3_275> is not
> > > > > > > close
> > > > > > > to <LBB3_274>.
> > > > > >
> > > > > > The cilium code has a lot of functions inlined and after inlining,
> > > > > > clang
> > > > > > may
> > > > > > do reordering based on its internal heuristics. It is totally possible
> > > > > > slight
> > > > > > code change may cause generated codes quite different.
> > > > > >
> > > > > > Regarding to
> > > > > > > and <LBB3_275> instruction 2198 is the one with "R1 invalid mem
> > > > > > > access
> > > > > > > 'inv'"
> > > > > >
> > > > > >
> > > > > > > 00000000000044a8 <LBB3_275>:
> > > > > > > ; __u8 new_ttl, ttl = ip4->ttl;
> > > > > > > 2197: 79 a1 38 ff 00 00 00 00 r1 = *(u64 *)(r10 - 200)
> > > > > > > 2198: 71 13 16 00 00 00 00 00 r3 = *(u8 *)(r1 + 22)
> > > > > > > ; if (ttl <= 1)
> > > > > > > 2199: 25 03 01 00 01 00 00 00 if r3 > 1 goto +1
> > > > > > > <LBB3_277>
> > > > > > > 2200: 05 00 20 ff 00 00 00 00 goto -224 <LBB3_253>
> > > > > >
> > > > > > Looks like "ip4" is spilled on the stack. and maybe the stack
> > > > > > save/restore
> > > > > > for
> > > > > > "ip4" does not preserve its original type.
> > > > > > This mostly happens to old kernels, I think.
> > > > > >
> > > > >
> > > > > the kernel 4.18 on Centos8, I also custom build most recent mainline git
> > > > > kernel 5.13 on Centos8, I recall I got same invaid memory access
> > > > >
> > > > > > If you have verifier log, it may help identify issues easily.
> > > > >
> > > > > Here is the complete verifer log, I skipped the BTF part
> > > > >
> > > > > level=warning msg="Prog section '2/7' rejected: Permission denied (13)!"
> > > > > subsys=datapath-loader
> > > > > level=warning msg=" - Type: 3" subsys=datapath-loader
> > > > > level=warning msg=" - Attach Type: 0" subsys=datapath-loader
> > > > > level=warning msg=" - Instructions: 2488 (0 over limit)"
> > > > > subsys=datapath-loader
> > > > > level=warning msg=" - License: GPL" subsys=datapath-loader
> > > > > level=warning subsys=datapath-loader
> > > > > level=warning msg="Verifier analysis:" subsys=datapath-loader
> > > > > level=warning subsys=datapath-loader
> > > > > level=warning msg="Skipped 158566 bytes, use 'verb' option for the full
> > > > > verbose log." subsys=datapath-loader
> > > > > level=warning msg="[...]" subsys=datapath-loader
> > > > > level=warning msg="-136=????00mm fp-144=00000000 fp-152=0000mmmm
> > > > > fp-160=????mmmm fp-168=mmmmmmmm fp-176=mmmmmmmm fp-184=ctx
> > > > > fp-192=mmmmmmmm
> > > > > fp-200=inv fp-208=mmmmmmmm fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm
> > > > > fp-240=inv128" subsys=datapath-loader
> > > > > level=warning msg="2437: (0f) r1 += r8" subsys=datapath-loader
> > > > > level=warning msg="2438: (7b) *(u64 *)(r0 +8) = r1"
> > > > > subsys=datapath-loader
> > > > > level=warning msg=" R0_w=map_value(id=0,off=0,ks=8,vs=16,imm=0)
> > > > > R1_w=inv(id=0) R6=ctx(id=0,off=0,imm=0)
> > > > > R7=inv(id=0,umax_value=128,var_off=(0x0; 0xff))
> > > > > R8=inv(id=0,umax_value=128,var_off=(0x0; 0xff)) R9=invP0 R10=fp0
> > > > > fp-8=mmmmmmmm fp-16=????mmmm fp-24=mmmmmmmm fp-32=mmmmmmmm
> > > > > fp-40=mmmmmmmm
> > > > > fp-48=mmmmmmmm fp-88=mmmmmmmm fp-96=00000000 fp-104=00000000
> > > > > fp-112=??mmmmmm fp-120=mmmmmmmm fp-128=??mmmmmm fp-136=????00mm
> > > > > fp-144=00000000 fp-152=0000mmmm fp-160=????mmmm fp-168=mmmmmmmm
> > > > > fp-176=mmmmmmmm fp-184=ctx fp-192=mmmmmmmm fp-200=inv fp-208=mmmmmmmm
> > > > > fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm fp-240=inv128"
> > > > > subsys=datapath-loader
> > > > > level=warning msg="2439: (05) goto pc+41" subsys=datapath-loader
> > > > > level=warning msg="2481: (18) r2 = 0x5c7" subsys=datapath-loader
> > > > > level=warning msg="2483: (67) r2 <<= 32" subsys=datapath-loader
> > > > > level=warning msg="2484: (77) r2 >>= 32" subsys=datapath-loader
> > > > > level=warning msg="2485: (b7) r1 = 6" subsys=datapath-loader
> > > > > level=warning msg="2486: (15) if r2 == 0x1 goto pc-341"
> > > > > subsys=datapath-loader
> > > > > level=warning msg="last_idx 2486 first_idx 2481" subsys=datapath-loader
> > > > > level=warning msg="regs=4 stack=0 before 2485: (b7) r1 = 6"
> > > > > subsys=datapath-loader
> > > > > level=warning msg="regs=4 stack=0 before 2484: (77) r2 >>= 32"
> > > > > subsys=datapath-loader
> > > > > level=warning msg="regs=4 stack=0 before 2483: (67) r2 <<= 32"
> > > > > subsys=datapath-loader
> > > > > level=warning msg="regs=4 stack=0 before 2481: (18) r2 = 0x5c7"
> > > > > subsys=datapath-loader
> > > > > level=warning msg="2487: (05) goto pc-344" subsys=datapath-loader
> > > > > level=warning msg="2144: (18) r1 = 0x5c7" subsys=datapath-loader
> > > > > level=warning msg="2146: (61) r2 = *(u32 *)(r6 +68)"
> > > > > subsys=datapath-loader
> > > > > level=warning msg="2147: (b7) r3 = 39" subsys=datapath-loader
> > > > > level=warning msg="2148: (63) *(u32 *)(r10 -76) = r3"
> > > > > subsys=datapath-loader
> > > > > level=warning msg="2149: (b7) r3 = 1" subsys=datapath-loader
> > > > > level=warning msg="2150: (6b) *(u16 *)(r10 -90) = r3"
> > > > > subsys=datapath-loader
> > > > > level=warning msg="2151: (63) *(u32 *)(r10 -96) = r8"
> > > > > subsys=datapath-loader
> > > > > level=warning msg="2152: (63) *(u32 *)(r10 -100) = r2"
> > > > > subsys=datapath-loader
> > > > > level=warning msg="2153: (18) r2 = 0x1d3" subsys=datapath-loader
> > > > > level=warning msg="2155: (6b) *(u16 *)(r10 -102) = r2"
> > > > > subsys=datapath-loader
> > > > > level=warning msg="2156: (b7) r2 = 1028" subsys=datapath-loader
> > > > > level=warning msg="2157: (6b) *(u16 *)(r10 -104) = r2"
> > > > > subsys=datapath-loader
> > > > > level=warning msg="2158: (b7) r2 = 0" subsys=datapath-loader
> > > > > level=warning msg="2159: (63) *(u32 *)(r10 -80) = r2"
> > > > > subsys=datapath-loader
> > > > > level=warning msg="last_idx 2159 first_idx 2481" subsys=datapath-loader
> > > > > level=warning msg="regs=4 stack=0 before 2158: (b7) r2 = 0"
> > > > > subsys=datapath-loader
> > > > > level=warning msg="2160: (63) *(u32 *)(r10 -84) = r2"
> > > > > subsys=datapath-loader
> > > > > level=warning msg="2161: (7b) *(u64 *)(r10 -72) = r2"
> > > > > subsys=datapath-loader
> > > > > level=warning msg="2162: (7b) *(u64 *)(r10 -64) = r2"
> > > > > subsys=datapath-loader
> > > > > level=warning msg="2163: (63) *(u32 *)(r10 -88) = r1"
> > > > > subsys=datapath-loader
> > > > > level=warning msg="2164: (6b) *(u16 *)(r10 -92) = r7"
> > > > > subsys=datapath-loader
> > > > > level=warning msg="2165: (67) r7 <<= 32" subsys=datapath-loader
> > > > > level=warning msg="2166: (18) r1 = 0xffffffff" subsys=datapath-loader
> > > > > level=warning msg="2168: (4f) r7 |= r1" subsys=datapath-loader
> > > > > level=warning msg="2169: (bf) r4 = r10" subsys=datapath-loader
> > > > > level=warning msg="2170: (07) r4 += -104" subsys=datapath-loader
> > > > > level=warning msg="2171: (bf) r1 = r6" subsys=datapath-loader
> > > > > level=warning msg="2172: (18) r2 = 0xffffa0c68cae1600"
> > > > > subsys=datapath-loader
> > > > > level=warning msg="2174: (bf) r3 = r7" subsys=datapath-loader
> > > > > level=warning msg="2175: (b7) r5 = 48" subsys=datapath-loader
> > > > > level=warning msg="2176: (85) call bpf_perf_event_output#25"
> > > > > subsys=datapath-loader
> > > > > level=warning msg="last_idx 2176 first_idx 2481" subsys=datapath-loader
> > > > > level=warning msg="regs=20 stack=0 before 2175: (b7) r5 = 48"
> > > > > subsys=datapath-loader
> > > > > level=warning msg="2177: (b7) r1 = 39" subsys=datapath-loader
> > > > > level=warning msg="2178: (b7) r2 = 0" subsys=datapath-loader
> > > > > level=warning msg="2179: (85) call bpf_redirect#23"
> > > > > subsys=datapath-loader
> > > > > level=warning msg="2180: (bf) r9 = r0" subsys=datapath-loader
> > > > > level=warning msg="2181: (bf) r1 = r9" subsys=datapath-loader
> > > > > level=warning msg="2182: (67) r1 <<= 32" subsys=datapath-loader
> > > > > level=warning msg="2183: (77) r1 >>= 32" subsys=datapath-loader
> > > > > level=warning msg="2184: (15) if r1 == 0x0 goto pc+57"
> > > > > subsys=datapath-loader
> > > > > level=warning msg=" R0_w=inv(id=0)
> > > > > R1_w=inv(id=0,umax_value=2147483647,var_off=(0x0; 0x7fffffff))
> > > > > R6=ctx(id=0,off=0,imm=0)
> > > > > R7=inv(id=0,umin_value=4294967295,umax_value=1099511627775,var_off=(0xffffffff;
> > > > > 0xff00000000),s32_min_value=-1,s32_max_value=0,u32_max_value=0)
> > > > > R8=inv(id=0,umax_value=128,var_off=(0x0; 0xff)) R9_w=inv(id=0) R10=fp0
> > > > > fp-8=mmmmmmmm fp-16=????mmmm fp-24=mmmmmmmm fp-32=mmmmmmmm
> > > > > fp-40=mmmmmmmm
> > > > > fp-48=mmmmmmmm fp-64=mmmmmmmm fp-72=mmmmmmmm fp-80=mmmmmmmm
> > > > > fp-88=mmmmmmmm
> > > > > fp-96=mmmmmmmm fp-104=mmmmmmmm fp-112=??mmmmmm fp-120=mmmmmmmm
> > > > > fp-128=??mmmmmm fp-136=????00mm fp-144=00000000 fp-152=0000mmmm
> > > > > fp-160=????mmmm fp-168=mmmmmmmm fp-176=mmmmmmmm fp-184=ctx
> > > > > fp-192=mmmmmmmm
> > > > > fp-200=inv fp-208=mmmmmmmm fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm
> > > > > fp-240=inv128" subsys=datapath-loader
> > > > > level=warning msg="2185: (18) r2 = 0xffffff60" subsys=datapath-loader
> > > > > level=warning msg="2187: (1d) if r1 == r2 goto pc+9"
> > > > > subsys=datapath-loader
> > > > > level=warning subsys=datapath-loader
> > > > > level=warning msg="from 2187 to 2197: R0=inv(id=0) R1=inv4294967136
> > > > > R2=inv4294967136 R6=ctx(id=0,off=0,imm=0)
> > > > > R7=inv(id=0,umin_value=4294967295,umax_value=1099511627775,var_off=(0xffffffff;
> > > > > 0xff00000000),s32_min_value=-1,s32_max_value=0,u32_max_value=0)
> > > > > R8=inv(id=0,umax_value=128,var_off=(0x0; 0xff)) R9=inv(id=0) R10=fp0
> > > > > fp-8=mmmmmmmm fp-16=????mmmm fp-24=mmmmmmmm fp-32=mmmmmmmm
> > > > > fp-40=mmmmmmmm
> > > > > fp-48=mmmmmmmm fp-64=mmmmmmmm fp-72=mmmmmmmm fp-80=mmmmmmmm
> > > > > fp-88=mmmmmmmm
> > > > > fp-96=mmmmmmmm fp-104=mmmmmmmm fp-112=??mmmmmm fp-120=mmmmmmmm
> > > > > fp-128=??mmmmmm fp-136=????00mm fp-144=00000000 fp-152=0000mmmm
> > > > > fp-160=????mmmm fp-168=mmmmmmmm fp-176=mmmmmmmm fp-184=ctx
> > > > > fp-192=mmmmmmmm
> > > > > fp-200=inv fp-208=mmmmmmmm fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm
> > > >
> > > > This is the problem. Here, we have "fp-200=inv" and
> > > > later on we have
> > > > r1 = *(u64 *)(r10 -200) // r1 is a unknown scalar
> > > >
> > > > We cannot do the following operation
> > > > r3 = *(u8 *)(r1 +22)
> > > > since r1 is a unknown scalar and the verifier rightfully rejected
> > > > the program.
> > > >
> > > > You need to examine complete log to find out why fp-200 stores
> > > > an "inv" (a unknown scalar).
> > >
> > > I guess you mean the complete log starting from the prog section 2/7 from
> > > verifier, if so, it seems fp-200 started with "inv"
> > >
> > > level=warning msg="Prog section '2/7' rejected: Permission denied (13)!"
> > > subsys=datapath-loader
> > >
> > > level=warning msg="-136=????00mm fp-144=00000000 fp-152=0000mmmm
> > > fp-160=????mmmm fp-168=mmmmmmmm fp-176=mmmmmmmm fp-184=ctx fp-192=mmmmmmmm
> > > fp-200=inv fp-208=mmmmmmmm fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm
> > > fp-240=inv128" subsys=datapath-loader
> > >
> > > and I don't see fp-200 ever changed to something else after, maybe I am
> > > reading it wrong
> >
> > The log is truncated.
> >
> > >>> level=warning msg="[...]" subsys=datapath-loader
> > >>> level=warning msg="-136=????00mm fp-144=00000000 fp-152=0000mmmm
> > >>> fp-160=????mmmm fp-168=mmmmmmmm fp-176=mmmmmmmm fp-184=ctx fp-192=mmmmmmmm
> > >>> fp-200=inv fp-208=mmmmmmmm fp-216=inv3 fp-224=mmmmmmmm fp-232=mmmmmmmm
> > >>> fp-240=inv128" subsys=datapath-loader
> > >>> level=warning msg="2437: (0f) r1 += r8" subsys=datapath-loader
> > >>> level=warning msg="2438: (7b) *(u64 *)(r0 +8) = r1" subsys=datapath-loader
> >
> > The log starts with insn 2437.
> > The complete log should start with insn 0.
>
> I see, it looks verb option need to be appended to the tc command I guess
> I will check with Cilium experts on appending the verb to the tc command
>
> level=error msg="Command execution failed" cmd="[tc filter replace dev
> lxc10a7b9a3c745 ingress prio 1 handle 1 bpf da obj 467_next/bpf_lxc.o sec
> from-container]" error="exit status 1" subsys=datapath-loader
>
> level=warning subsys=datapath-loader
> level=warning msg="BTF debug data section '.BTF' rejected: Invalid
> argument (22)!" subsys=datapath-loader
> level=warning msg=" - Length: 24779" subsys=datapath-loader
> level=warning msg="Verifier analysis:" subsys=datapath-loader
> level=warning subsys=datapath-loader
>
> level=warning msg="Skipped 787 bytes, use 'verb' option for the full
> verbose log." subsys=datapath-loader
after a quick look, I might just need to append the verb here
tc filter replace dev $DEV $WHERE prio 1 handle 1 bpf da obj $OUT sec $SEC
in bpf_load in cilium bpf/init.sh, I will try to get the full log,
appreciate your patience and help :)
>
> >
> > >
> > > >
> > > > > fp-240=inv128" subsys=datapath-loader
> > > > > level=warning msg="2197: (79) r1 = *(u64 *)(r10 -200)"
> > > > > subsys=datapath-loader
> > > > > level=warning msg="2198: (71) r3 = *(u8 *)(r1 +22)"
> > > > > subsys=datapath-loader
> > > > > level=warning msg="R1 invalid mem access 'inv'" subsys=datapath-loader
> > > > > level=warning msg="processed 1802 insns (limit 1000000)
> > > > > max_states_per_insn 4 total_states 103 peak_states 103 mark_read 49"
> > > > > subsys=datapath-loader
> > > > > level=warning subsys=datapath-loader
> > > > > level=warning msg="Error filling program arrays!" subsys=datapath-loader
> > > > > level=warning msg="Unable to load program" subsys=datapath-loader
> > > > >
> > > > >
> > > > > > >
> > > > > > >
> > > > > > > 2, Can I assume the verifier is to simulate the order of BPF byte
> > > > > > > code execution in run time, like if without any jump or goto in
> > > > > > > <LBB3_274>, <LBB3_275> will be executed after <LBB3_274>?
> > > > > >
> > > > > > The verifier will try to verify both paths, jumping to LBB3_289
> > > > > > or fall back to LBB3_275.
> > > > > >
> > > > > > >
> > > > > > >
> > > > > > >
> > > > > > > Enterprise Network Engineer
> > > > > > > F5 Networks Inc
> > > > > > > https://www.youtube.com/c/VincentLi
> > > > > > >
> > > > > >
> > > >
> >
>
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: R1 invalid mem access 'inv'
[not found] ` <CAK3+h2xv-EZH9afEymGqKdwHozHHu=XHJYKispFSixYxz7YVLQ@mail.gmail.com>
@ 2021-07-12 23:38 ` Vincent Li
2021-07-13 15:46 ` Yonghong Song
0 siblings, 1 reply; 12+ messages in thread
From: Vincent Li @ 2021-07-12 23:38 UTC (permalink / raw)
To: Yonghong Song; +Cc: bpf
Hi Yonghong,
On Fri, Jun 18, 2021 at 12:58 PM Vincent Li <vincent.mc.li@gmail.com> wrote:
>
> Hi Yonghong,
>
> I attached the full verifier log and BPF bytecode just in case it is
> obvious to you, if it is not, that is ok. I tried to make sense out of
> it and I failed due to my limited knowledge about BPF :)
>
I followed your clue on investigating how fp-200=pkt changed to
fp-200=inv in https://github.com/cilium/cilium/issues/16517#issuecomment-873522146
with previous attached complete bpf verifier log and bpf bytecode, it
eventually comes to following
0000000000004948 :
2345: bf a3 00 00 00 00 00 00 r3 = r10
2346: 07 03 00 00 d0 ff ff ff r3 += -48
2347: b7 08 00 00 06 00 00 00 r8 = 6
; return ctx_store_bytes(ctx, off, mac, ETH_ALEN, 0);
2348: bf 61 00 00 00 00 00 00 r1 = r6
2349: b7 02 00 00 00 00 00 00 r2 = 0
2350: b7 04 00 00 06 00 00 00 r4 = 6
2351: b7 05 00 00 00 00 00 00 r5 = 0
2352: 85 00 00 00 09 00 00 00 call 9
2353: 67 00 00 00 20 00 00 00 r0 <<= 32
2354: c7 00 00 00 20 00 00 00 r0 s>>= 32
; if (eth_store_daddr(ctx, (__u8 *) &vtep_mac.addr, 0) < 0)
2355: c5 00 54 00 00 00 00 00 if r0 s< 0 goto +84
my new code is eth_store_daddr(ctx, (__u8 *) &vtep_mac.addr, 0) < 0;
that is what i copied from other part of cilium code, eth_store_daddr
is:
static __always_inline int eth_store_daddr(struct __ctx_buff *ctx,
const __u8 *mac, int off)
{
#if !CTX_DIRECT_WRITE_OK
return eth_store_daddr_aligned(ctx, mac, off);
#else
......
}
and eth_store_daddr_aligned is
static __always_inline int eth_store_daddr_aligned(struct __ctx_buff *ctx,
const __u8 *mac, int off)
{
return ctx_store_bytes(ctx, off, mac, ETH_ALEN, 0);
}
Joe from Cilium raised an interesting question on why the compiler
put ctx_store_bytes() before if (eth_store_daddr(ctx, (__u8 *)
&vtep_mac.addr, 0) < 0),
that seems to have fp-200=pkt changed to fp-200=inv, and indeed if I
skip the eth_store_daddr_aligned call, the issue is resolved, do you
have clue on why compiler does that?
I have more follow-up in https://github.com/cilium/cilium/issues/16517
if you are interested to know the full picture.
Appreciate it very much if you have time to look at it :)
Vincent
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: R1 invalid mem access 'inv'
2021-07-12 23:38 ` Vincent Li
@ 2021-07-13 15:46 ` Yonghong Song
2021-07-16 1:33 ` Vincent Li
0 siblings, 1 reply; 12+ messages in thread
From: Yonghong Song @ 2021-07-13 15:46 UTC (permalink / raw)
To: Vincent Li; +Cc: bpf
On 7/12/21 4:38 PM, Vincent Li wrote:
> Hi Yonghong,
>
>
>
> On Fri, Jun 18, 2021 at 12:58 PM Vincent Li <vincent.mc.li@gmail.com> wrote:
>>
>> Hi Yonghong,
>>
>> I attached the full verifier log and BPF bytecode just in case it is
>> obvious to you, if it is not, that is ok. I tried to make sense out of
>> it and I failed due to my limited knowledge about BPF :)
>>
>
> I followed your clue on investigating how fp-200=pkt changed to
> fp-200=inv in https://github.com/cilium/cilium/issues/16517#issuecomment-873522146
> with previous attached complete bpf verifier log and bpf bytecode, it
> eventually comes to following
>
> 0000000000004948 :
> 2345: bf a3 00 00 00 00 00 00 r3 = r10
> 2346: 07 03 00 00 d0 ff ff ff r3 += -48
> 2347: b7 08 00 00 06 00 00 00 r8 = 6
> ; return ctx_store_bytes(ctx, off, mac, ETH_ALEN, 0);
> 2348: bf 61 00 00 00 00 00 00 r1 = r6
> 2349: b7 02 00 00 00 00 00 00 r2 = 0
> 2350: b7 04 00 00 06 00 00 00 r4 = 6
> 2351: b7 05 00 00 00 00 00 00 r5 = 0
> 2352: 85 00 00 00 09 00 00 00 call 9
> 2353: 67 00 00 00 20 00 00 00 r0 <<= 32
> 2354: c7 00 00 00 20 00 00 00 r0 s>>= 32
> ; if (eth_store_daddr(ctx, (__u8 *) &vtep_mac.addr, 0) < 0)
> 2355: c5 00 54 00 00 00 00 00 if r0 s< 0 goto +84
>
> my new code is eth_store_daddr(ctx, (__u8 *) &vtep_mac.addr, 0) < 0;
> that is what i copied from other part of cilium code, eth_store_daddr
> is:
>
> static __always_inline int eth_store_daddr(struct __ctx_buff *ctx,
>
> const __u8 *mac, int off)
> {
> #if !CTX_DIRECT_WRITE_OK
> return eth_store_daddr_aligned(ctx, mac, off);
> #else
> ......
> }
>
> and eth_store_daddr_aligned is
>
> static __always_inline int eth_store_daddr_aligned(struct __ctx_buff *ctx,
>
> const __u8 *mac, int off)
> {
> return ctx_store_bytes(ctx, off, mac, ETH_ALEN, 0);
> }
>
> Joe from Cilium raised an interesting question on why the compiler
> put ctx_store_bytes() before if (eth_store_daddr(ctx, (__u8 *)
> &vtep_mac.addr, 0) < 0),
> that seems to have fp-200=pkt changed to fp-200=inv, and indeed if I
> skip the eth_store_daddr_aligned call, the issue is resolved, do you
> have clue on why compiler does that?
This is expected. After inlining, you got
if (ctx_store_bytes(...) < 0) ...
So you need to do
ctx_store_bytes(...)
first and then do the if condition.
Looking at the issue at https://github.com/cilium/cilium/issues/16517,
the reason seems due to xdp_store_bytes/skb_store_bytes.
When these helpers write some data into the stack based buffer, they
invalidate some stack contents. I don't know whether it is a false
postive case or not, i.e., the verifier invalidates the wrong stack
location conservatively. This needs further investigation.
>
> I have more follow-up in https://github.com/cilium/cilium/issues/16517
> if you are interested to know the full picture.
>
> Appreciate it very much if you have time to look at it :)
>
> Vincent
>
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: R1 invalid mem access 'inv'
2021-07-13 15:46 ` Yonghong Song
@ 2021-07-16 1:33 ` Vincent Li
2021-09-19 1:46 ` Vincent Li
0 siblings, 1 reply; 12+ messages in thread
From: Vincent Li @ 2021-07-16 1:33 UTC (permalink / raw)
To: Yonghong Song; +Cc: bpf
Thanks Yonghong for looking into this.
On Tue, Jul 13, 2021 at 8:46 AM Yonghong Song <yhs@fb.com> wrote:
>
>
>
> On 7/12/21 4:38 PM, Vincent Li wrote:
> > Hi Yonghong,
> >
> >
> >
> > On Fri, Jun 18, 2021 at 12:58 PM Vincent Li <vincent.mc.li@gmail.com> wrote:
> >>
> >> Hi Yonghong,
> >>
> >> I attached the full verifier log and BPF bytecode just in case it is
> >> obvious to you, if it is not, that is ok. I tried to make sense out of
> >> it and I failed due to my limited knowledge about BPF :)
> >>
> >
> > I followed your clue on investigating how fp-200=pkt changed to
> > fp-200=inv in https://github.com/cilium/cilium/issues/16517#issuecomment-873522146
> > with previous attached complete bpf verifier log and bpf bytecode, it
> > eventually comes to following
> >
> > 0000000000004948 :
> > 2345: bf a3 00 00 00 00 00 00 r3 = r10
> > 2346: 07 03 00 00 d0 ff ff ff r3 += -48
> > 2347: b7 08 00 00 06 00 00 00 r8 = 6
> > ; return ctx_store_bytes(ctx, off, mac, ETH_ALEN, 0);
> > 2348: bf 61 00 00 00 00 00 00 r1 = r6
> > 2349: b7 02 00 00 00 00 00 00 r2 = 0
> > 2350: b7 04 00 00 06 00 00 00 r4 = 6
> > 2351: b7 05 00 00 00 00 00 00 r5 = 0
> > 2352: 85 00 00 00 09 00 00 00 call 9
> > 2353: 67 00 00 00 20 00 00 00 r0 <<= 32
> > 2354: c7 00 00 00 20 00 00 00 r0 s>>= 32
> > ; if (eth_store_daddr(ctx, (__u8 *) &vtep_mac.addr, 0) < 0)
> > 2355: c5 00 54 00 00 00 00 00 if r0 s< 0 goto +84
> >
> > my new code is eth_store_daddr(ctx, (__u8 *) &vtep_mac.addr, 0) < 0;
> > that is what i copied from other part of cilium code, eth_store_daddr
> > is:
> >
> > static __always_inline int eth_store_daddr(struct __ctx_buff *ctx,
> >
> > const __u8 *mac, int off)
> > {
> > #if !CTX_DIRECT_WRITE_OK
> > return eth_store_daddr_aligned(ctx, mac, off);
> > #else
> > ......
> > }
> >
> > and eth_store_daddr_aligned is
> >
> > static __always_inline int eth_store_daddr_aligned(struct __ctx_buff *ctx,
> >
> > const __u8 *mac, int off)
> > {
> > return ctx_store_bytes(ctx, off, mac, ETH_ALEN, 0);
> > }
> >
> > Joe from Cilium raised an interesting question on why the compiler
> > put ctx_store_bytes() before if (eth_store_daddr(ctx, (__u8 *)
> > &vtep_mac.addr, 0) < 0),
> > that seems to have fp-200=pkt changed to fp-200=inv, and indeed if I
> > skip the eth_store_daddr_aligned call, the issue is resolved, do you
> > have clue on why compiler does that?
>
> This is expected. After inlining, you got
> if (ctx_store_bytes(...) < 0) ...
>
> So you need to do
> ctx_store_bytes(...)
> first and then do the if condition.
>
I got workaround which is not to use eth_store_daddr_aligned, but use
__builtin_memcpy() according to
cilium commit 9c857217834 (bpf: optimized memcpy/memzero with dw-wide copies)
> Looking at the issue at https://github.com/cilium/cilium/issues/16517,
> the reason seems due to xdp_store_bytes/skb_store_bytes.
> When these helpers write some data into the stack based buffer, they
> invalidate some stack contents. I don't know whether it is a false
> postive case or not, i.e., the verifier invalidates the wrong stack
> location conservatively. This needs further investigation.
>
glad to know it is not something silly that I am doing, hope it can be
figured out eventually someday :)
>
> >
> > I have more follow-up in https://github.com/cilium/cilium/issues/16517
> > if you are interested to know the full picture.
> >
> > Appreciate it very much if you have time to look at it :)
> >
> > Vincent
> >
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: R1 invalid mem access 'inv'
2021-07-16 1:33 ` Vincent Li
@ 2021-09-19 1:46 ` Vincent Li
0 siblings, 0 replies; 12+ messages in thread
From: Vincent Li @ 2021-09-19 1:46 UTC (permalink / raw)
To: Yonghong Song; +Cc: bpf
On Thu, Jul 15, 2021 at 6:33 PM Vincent Li <vincent.mc.li@gmail.com> wrote:
>
> Thanks Yonghong for looking into this.
>
> On Tue, Jul 13, 2021 at 8:46 AM Yonghong Song <yhs@fb.com> wrote:
> >
> >
> >
> > On 7/12/21 4:38 PM, Vincent Li wrote:
> > > Hi Yonghong,
> > >
> > >
> > >
> > > On Fri, Jun 18, 2021 at 12:58 PM Vincent Li <vincent.mc.li@gmail.com> wrote:
> > >>
> > >> Hi Yonghong,
> > >>
> > >> I attached the full verifier log and BPF bytecode just in case it is
> > >> obvious to you, if it is not, that is ok. I tried to make sense out of
> > >> it and I failed due to my limited knowledge about BPF :)
> > >>
> > >
> > > I followed your clue on investigating how fp-200=pkt changed to
> > > fp-200=inv in https://github.com/cilium/cilium/issues/16517#issuecomment-873522146
> > > with previous attached complete bpf verifier log and bpf bytecode, it
> > > eventually comes to following
> > >
> > > 0000000000004948 :
> > > 2345: bf a3 00 00 00 00 00 00 r3 = r10
> > > 2346: 07 03 00 00 d0 ff ff ff r3 += -48
> > > 2347: b7 08 00 00 06 00 00 00 r8 = 6
> > > ; return ctx_store_bytes(ctx, off, mac, ETH_ALEN, 0);
> > > 2348: bf 61 00 00 00 00 00 00 r1 = r6
> > > 2349: b7 02 00 00 00 00 00 00 r2 = 0
> > > 2350: b7 04 00 00 06 00 00 00 r4 = 6
> > > 2351: b7 05 00 00 00 00 00 00 r5 = 0
> > > 2352: 85 00 00 00 09 00 00 00 call 9
> > > 2353: 67 00 00 00 20 00 00 00 r0 <<= 32
> > > 2354: c7 00 00 00 20 00 00 00 r0 s>>= 32
> > > ; if (eth_store_daddr(ctx, (__u8 *) &vtep_mac.addr, 0) < 0)
> > > 2355: c5 00 54 00 00 00 00 00 if r0 s< 0 goto +84
> > >
> > > my new code is eth_store_daddr(ctx, (__u8 *) &vtep_mac.addr, 0) < 0;
> > > that is what i copied from other part of cilium code, eth_store_daddr
> > > is:
> > >
> > > static __always_inline int eth_store_daddr(struct __ctx_buff *ctx,
> > >
> > > const __u8 *mac, int off)
> > > {
> > > #if !CTX_DIRECT_WRITE_OK
> > > return eth_store_daddr_aligned(ctx, mac, off);
> > > #else
> > > ......
> > > }
> > >
> > > and eth_store_daddr_aligned is
> > >
> > > static __always_inline int eth_store_daddr_aligned(struct __ctx_buff *ctx,
> > >
> > > const __u8 *mac, int off)
> > > {
> > > return ctx_store_bytes(ctx, off, mac, ETH_ALEN, 0);
> > > }
> > >
> > > Joe from Cilium raised an interesting question on why the compiler
> > > put ctx_store_bytes() before if (eth_store_daddr(ctx, (__u8 *)
> > > &vtep_mac.addr, 0) < 0),
> > > that seems to have fp-200=pkt changed to fp-200=inv, and indeed if I
> > > skip the eth_store_daddr_aligned call, the issue is resolved, do you
> > > have clue on why compiler does that?
> >
> > This is expected. After inlining, you got
> > if (ctx_store_bytes(...) < 0) ...
> >
> > So you need to do
> > ctx_store_bytes(...)
> > first and then do the if condition.
> >
>
> I got workaround which is not to use eth_store_daddr_aligned, but use
> __builtin_memcpy() according to
> cilium commit 9c857217834 (bpf: optimized memcpy/memzero with dw-wide copies)
>
> > Looking at the issue at https://github.com/cilium/cilium/issues/16517,
> > the reason seems due to xdp_store_bytes/skb_store_bytes.
> > When these helpers write some data into the stack based buffer, they
> > invalidate some stack contents. I don't know whether it is a false
> > postive case or not, i.e., the verifier invalidates the wrong stack
> > location conservatively. This needs further investigation.
> >
> glad to know it is not something silly that I am doing, hope it can be
> figured out eventually someday :)
>
> >
> > >
> > > I have more follow-up in https://github.com/cilium/cilium/issues/16517
> > > if you are interested to know the full picture.
> > >
> > > Appreciate it very much if you have time to look at it :)
> > >
> > > Vincent
> > >
oops, I meant to this one, Finally bring an end to my long time
mystery issue of using
eth_store_daddr() result in "invalid mem access", I need to initialize
the mac address variable
with 0, uninitialized variable also cause "invalid read from stack
off" in kernel 4.9, but not
version above 4.9.
https://github.com/cilium/cilium/pull/17370#issuecomment-922396415
^ permalink raw reply [flat|nested] 12+ messages in thread
end of thread, other threads:[~2021-09-19 1:46 UTC | newest]
Thread overview: 12+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-06-17 0:05 R1 invalid mem access 'inv' Vincent Li
2021-06-17 6:02 ` Yonghong Song
2021-06-17 14:19 ` Vincent Li
2021-06-17 16:32 ` Yonghong Song
2021-06-17 22:19 ` Vincent Li
2021-06-18 0:51 ` Yonghong Song
2021-06-18 3:58 ` Vincent Li
2021-06-18 4:15 ` Vincent Li
[not found] ` <CAK3+h2xv-EZH9afEymGqKdwHozHHu=XHJYKispFSixYxz7YVLQ@mail.gmail.com>
2021-07-12 23:38 ` Vincent Li
2021-07-13 15:46 ` Yonghong Song
2021-07-16 1:33 ` Vincent Li
2021-09-19 1:46 ` Vincent Li
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.