* 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
[parent not found: <CAK3+h2xv-EZH9afEymGqKdwHozHHu=XHJYKispFSixYxz7YVLQ@mail.gmail.com>]
* 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.