* [BUG] hitting bug when running spinlock test @ 2021-03-04 19:03 Jiri Olsa 2021-03-05 4:08 ` Yonghong Song 2021-03-05 20:38 ` Roman Gushchin 0 siblings, 2 replies; 9+ messages in thread From: Jiri Olsa @ 2021-03-04 19:03 UTC (permalink / raw) To: Alexei Starovoitov, Daniel Borkmann, Roman Gushchin, YiFei Zhu Cc: Andrii Nakryiko, netdev, bpf, Martin KaFai Lau, Song Liu, Yonghong Song, John Fastabend, KP Singh, Toke Høiland-Jørgensen, Yauheni Kaliuta, Jiri Benc, Hangbin Liu hi, I'm getting attached BUG/crash when running in parralel selftests, like: while :; do ./test_progs -t spinlock; done while :; do ./test_progs ; done it's the latest bpf-next/master, I can send the .config if needed, but I don't think there's anything special about it, because I saw the bug on other servers with different generic configs it looks like it's related to cgroup local storage, for some reason the storage deref returns NULL I'm bit lost in this code, so any help would be great ;-) thanks, jirka --- ... [ 382.324440] bpf_testmod: loading out-of-tree module taints kernel. [ 382.330670] bpf_testmod: module verification failed: signature and/or required key missing - tainting kernel [ 480.391667] perf: interrupt took too long (2540 > 2500), lowering kernel.perf_event_max_sample_rate to 78000 [ 480.401730] perf: interrupt took too long (6860 > 6751), lowering kernel.perf_event_max_sample_rate to 29000 [ 480.416172] perf: interrupt took too long (8602 > 8575), lowering kernel.perf_event_max_sample_rate to 23000 [ 480.433053] BUG: kernel NULL pointer dereference, address: 0000000000000000 [ 480.440014] #PF: supervisor read access in kernel mode [ 480.445153] #PF: error_code(0x0000) - not-present page [ 480.450294] PGD 8000000133a18067 P4D 8000000133a18067 PUD 10c019067 PMD 0 [ 480.457164] Oops: 0000 [#1] PREEMPT SMP PTI [ 480.461350] CPU: 6 PID: 16689 Comm: test_progs Tainted: G IOE 5.11.0+ #11 [ 480.469263] Hardware name: Dell Inc. PowerEdge R440/08CYF7, BIOS 1.7.0 12/14/2018 [ 480.476742] RIP: 0010:bpf_get_local_storage+0x13/0x50 [ 480.481797] Code: e8 92 c5 8e 00 5d 89 c0 c3 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 00 0f 1f 44 00 00 83 7f 18 15 74 10 65 48 8b 05 6d c6 e2 7e <48> 8b 00 48 83 c0 10 c3 55 48 89 e5 53 65 48 8b 05 60 c6 e2 7e8 [ 480.500540] RSP: 0018:ffffc90001bd3ce0 EFLAGS: 00010293 [ 480.505766] RAX: 0000000000000000 RBX: 982a259500000000 RCX: 0000000000000018 [ 480.512901] RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffff888149ccf000 [ 480.520034] RBP: ffffc90001bd3d20 R08: ffffc90001bd3d04 R09: ffff888105121600 [ 480.527164] R10: d3b9342000000000 R11: 000000000000025c R12: 0000000000000734 [ 480.534299] R13: ffff888149ccc710 R14: 0000000000000000 R15: ffffc90000379048 [ 480.541430] FS: 00007f8f2357b640(0000) GS:ffff8897e0980000(0000) knlGS:0000000000000000 [ 480.549515] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 480.555262] CR2: 0000000000000000 CR3: 000000014e826006 CR4: 00000000007706e0 [ 480.562395] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [ 480.569527] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 [ 480.576660] PKRU: 55555554 [ 480.579372] Call Trace: [ 480.581829] ? bpf_prog_c48154a736e5c014_bpf_sping_lock_test+0x2ba/0x860 [ 480.588526] bpf_test_run+0x127/0x2b0 [ 480.592192] ? __build_skb_around+0xb0/0xc0 [ 480.596378] bpf_prog_test_run_skb+0x32f/0x6b0 [ 480.600824] __do_sys_bpf+0xa94/0x2240 [ 480.604577] ? debug_smp_processor_id+0x17/0x20 [ 480.609107] ? __perf_event_task_sched_in+0x32/0x340 [ 480.614077] __x64_sys_bpf+0x1a/0x20 [ 480.617653] do_syscall_64+0x38/0x50 [ 480.621233] entry_SYSCALL_64_after_hwframe+0x44/0xae [ 480.626286] RIP: 0033:0x7f8f2467f55d [ 480.629865] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d eb 78 0c 00 f7 d8 64 89 018 [ 480.648611] RSP: 002b:00007f8f2357ad58 EFLAGS: 00000206 ORIG_RAX: 0000000000000141 [ 480.656175] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f8f2467f55d [ 480.663308] RDX: 0000000000000078 RSI: 00007f8f2357ad60 RDI: 000000000000000a [ 480.670442] RBP: 00007f8f2357ae28 R08: 0000000000000000 R09: 0000000000000008 [ 480.677574] R10: 0000000000000000 R11: 0000000000000206 R12: 00007f8f2357ae2c [ 480.684707] R13: 00000000022df420 R14: 0000000000000000 R15: 00007f8f2357b640 [ 480.691842] Modules linked in: bpf_testmod(OE) intel_rapl_msr intel_rapl_common x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm ipmi_ssif irqbypass rapl intel_cstate dell_smbios intel_uncore mei_] [ 480.739134] CR2: 0000000000000000 [ 480.742452] ---[ end trace 807177cbb5e3b3da ]--- [ 480.752174] RIP: 0010:bpf_get_local_storage+0x13/0x50 [ 480.757230] Code: e8 92 c5 8e 00 5d 89 c0 c3 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 00 0f 1f 44 00 00 83 7f 18 15 74 10 65 48 8b 05 6d c6 e2 7e <48> 8b 00 48 83 c0 10 c3 55 48 89 e5 53 65 48 8b 05 60 c6 e2 7e8 [ 480.775976] RSP: 0018:ffffc90001bd3ce0 EFLAGS: 00010293 [ 480.781202] RAX: 0000000000000000 RBX: 982a259500000000 RCX: 0000000000000018 [ 480.788335] RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffff888149ccf000 [ 480.795466] RBP: ffffc90001bd3d20 R08: ffffc90001bd3d04 R09: ffff888105121600 [ 480.802598] R10: d3b9342000000000 R11: 000000000000025c R12: 0000000000000734 [ 480.809730] R13: ffff888149ccc710 R14: 0000000000000000 R15: ffffc90000379048 [ 480.816865] FS: 00007f8f2357b640(0000) GS:ffff8897e0980000(0000) knlGS:0000000000000000 [ 480.824951] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 480.830695] CR2: 0000000000000000 CR3: 000000014e826006 CR4: 00000000007706e0 [ 480.837829] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [ 480.844961] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 [ 480.852093] PKRU: 55555554 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: [BUG] hitting bug when running spinlock test 2021-03-04 19:03 [BUG] hitting bug when running spinlock test Jiri Olsa @ 2021-03-05 4:08 ` Yonghong Song 2021-03-05 20:38 ` Roman Gushchin 1 sibling, 0 replies; 9+ messages in thread From: Yonghong Song @ 2021-03-05 4:08 UTC (permalink / raw) To: Jiri Olsa, Alexei Starovoitov, Daniel Borkmann, Roman Gushchin, YiFei Zhu Cc: Andrii Nakryiko, netdev, bpf, Martin KaFai Lau, Song Liu, John Fastabend, KP Singh, Toke Høiland-Jørgensen, Yauheni Kaliuta, Jiri Benc, Hangbin Liu On 3/4/21 11:03 AM, Jiri Olsa wrote: > hi, > I'm getting attached BUG/crash when running in parralel selftests, like: > > while :; do ./test_progs -t spinlock; done > while :; do ./test_progs ; done > > it's the latest bpf-next/master, I can send the .config if needed, > but I don't think there's anything special about it, because I saw > the bug on other servers with different generic configs > > it looks like it's related to cgroup local storage, for some reason > the storage deref returns NULL I checked assembly, I think you are right. percpu bpf_cgroup_storage[stype] seems null. This array is set by bpf_cgroup_storage_set() which is called inside BPF_PROG_RUN_ARRAY_FLAGS and __BPF_PROG_RUN_ARRAY_FLAGS. You could check their parameter *array* input to see why the NULL value is set. I tried your above two commands with latest net-next and can reproduce the failure. I will take a further look. Thanks! > > I'm bit lost in this code, so any help would be great ;-) > > thanks, > jirka > > > --- > ... > [ 382.324440] bpf_testmod: loading out-of-tree module taints kernel. > [ 382.330670] bpf_testmod: module verification failed: signature and/or required key missing - tainting kernel > [ 480.391667] perf: interrupt took too long (2540 > 2500), lowering kernel.perf_event_max_sample_rate to 78000 > [ 480.401730] perf: interrupt took too long (6860 > 6751), lowering kernel.perf_event_max_sample_rate to 29000 > [ 480.416172] perf: interrupt took too long (8602 > 8575), lowering kernel.perf_event_max_sample_rate to 23000 > [ 480.433053] BUG: kernel NULL pointer dereference, address: 0000000000000000 > [ 480.440014] #PF: supervisor read access in kernel mode > [ 480.445153] #PF: error_code(0x0000) - not-present page > [ 480.450294] PGD 8000000133a18067 P4D 8000000133a18067 PUD 10c019067 PMD 0 > [ 480.457164] Oops: 0000 [#1] PREEMPT SMP PTI > [ 480.461350] CPU: 6 PID: 16689 Comm: test_progs Tainted: G IOE 5.11.0+ #11 > [ 480.469263] Hardware name: Dell Inc. PowerEdge R440/08CYF7, BIOS 1.7.0 12/14/2018 > [ 480.476742] RIP: 0010:bpf_get_local_storage+0x13/0x50 > [ 480.481797] Code: e8 92 c5 8e 00 5d 89 c0 c3 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 00 0f 1f 44 00 00 83 7f 18 15 74 10 65 48 8b 05 6d c6 e2 7e <48> 8b 00 48 83 c0 10 c3 55 48 89 e5 53 65 48 8b 05 60 c6 e2 7e8 > [ 480.500540] RSP: 0018:ffffc90001bd3ce0 EFLAGS: 00010293 > [ 480.505766] RAX: 0000000000000000 RBX: 982a259500000000 RCX: 0000000000000018 > [ 480.512901] RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffff888149ccf000 > [ 480.520034] RBP: ffffc90001bd3d20 R08: ffffc90001bd3d04 R09: ffff888105121600 > [ 480.527164] R10: d3b9342000000000 R11: 000000000000025c R12: 0000000000000734 > [ 480.534299] R13: ffff888149ccc710 R14: 0000000000000000 R15: ffffc90000379048 > [ 480.541430] FS: 00007f8f2357b640(0000) GS:ffff8897e0980000(0000) knlGS:0000000000000000 > [ 480.549515] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > [ 480.555262] CR2: 0000000000000000 CR3: 000000014e826006 CR4: 00000000007706e0 > [ 480.562395] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 > [ 480.569527] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 > [ 480.576660] PKRU: 55555554 > [ 480.579372] Call Trace: > [ 480.581829] ? bpf_prog_c48154a736e5c014_bpf_sping_lock_test+0x2ba/0x860 > [ 480.588526] bpf_test_run+0x127/0x2b0 > [ 480.592192] ? __build_skb_around+0xb0/0xc0 > [ 480.596378] bpf_prog_test_run_skb+0x32f/0x6b0 > [ 480.600824] __do_sys_bpf+0xa94/0x2240 > [ 480.604577] ? debug_smp_processor_id+0x17/0x20 > [ 480.609107] ? __perf_event_task_sched_in+0x32/0x340 > [ 480.614077] __x64_sys_bpf+0x1a/0x20 > [ 480.617653] do_syscall_64+0x38/0x50 > [ 480.621233] entry_SYSCALL_64_after_hwframe+0x44/0xae > [ 480.626286] RIP: 0033:0x7f8f2467f55d > [ 480.629865] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d eb 78 0c 00 f7 d8 64 89 018 > [ 480.648611] RSP: 002b:00007f8f2357ad58 EFLAGS: 00000206 ORIG_RAX: 0000000000000141 > [ 480.656175] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f8f2467f55d > [ 480.663308] RDX: 0000000000000078 RSI: 00007f8f2357ad60 RDI: 000000000000000a > [ 480.670442] RBP: 00007f8f2357ae28 R08: 0000000000000000 R09: 0000000000000008 > [ 480.677574] R10: 0000000000000000 R11: 0000000000000206 R12: 00007f8f2357ae2c > [ 480.684707] R13: 00000000022df420 R14: 0000000000000000 R15: 00007f8f2357b640 > [ 480.691842] Modules linked in: bpf_testmod(OE) intel_rapl_msr intel_rapl_common x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm ipmi_ssif irqbypass rapl intel_cstate dell_smbios intel_uncore mei_] > [ 480.739134] CR2: 0000000000000000 > [ 480.742452] ---[ end trace 807177cbb5e3b3da ]--- > [ 480.752174] RIP: 0010:bpf_get_local_storage+0x13/0x50 > [ 480.757230] Code: e8 92 c5 8e 00 5d 89 c0 c3 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 00 0f 1f 44 00 00 83 7f 18 15 74 10 65 48 8b 05 6d c6 e2 7e <48> 8b 00 48 83 c0 10 c3 55 48 89 e5 53 65 48 8b 05 60 c6 e2 7e8 > [ 480.775976] RSP: 0018:ffffc90001bd3ce0 EFLAGS: 00010293 > [ 480.781202] RAX: 0000000000000000 RBX: 982a259500000000 RCX: 0000000000000018 > [ 480.788335] RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffff888149ccf000 > [ 480.795466] RBP: ffffc90001bd3d20 R08: ffffc90001bd3d04 R09: ffff888105121600 > [ 480.802598] R10: d3b9342000000000 R11: 000000000000025c R12: 0000000000000734 > [ 480.809730] R13: ffff888149ccc710 R14: 0000000000000000 R15: ffffc90000379048 > [ 480.816865] FS: 00007f8f2357b640(0000) GS:ffff8897e0980000(0000) knlGS:0000000000000000 > [ 480.824951] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > [ 480.830695] CR2: 0000000000000000 CR3: 000000014e826006 CR4: 00000000007706e0 > [ 480.837829] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 > [ 480.844961] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 > [ 480.852093] PKRU: 55555554 > ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: [BUG] hitting bug when running spinlock test 2021-03-04 19:03 [BUG] hitting bug when running spinlock test Jiri Olsa 2021-03-05 4:08 ` Yonghong Song @ 2021-03-05 20:38 ` Roman Gushchin 2021-03-05 21:10 ` Yonghong Song 1 sibling, 1 reply; 9+ messages in thread From: Roman Gushchin @ 2021-03-05 20:38 UTC (permalink / raw) To: Jiri Olsa Cc: Alexei Starovoitov, Daniel Borkmann, YiFei Zhu, Andrii Nakryiko, netdev, bpf, Martin KaFai Lau, Song Liu, Yonghong Song, John Fastabend, KP Singh, Toke Høiland-Jørgensen, Yauheni Kaliuta, Jiri Benc, Hangbin Liu, Stanislav Fomichev On Thu, Mar 04, 2021 at 08:03:33PM +0100, Jiri Olsa wrote: > hi, > I'm getting attached BUG/crash when running in parralel selftests, like: > > while :; do ./test_progs -t spinlock; done > while :; do ./test_progs ; done > > it's the latest bpf-next/master, I can send the .config if needed, > but I don't think there's anything special about it, because I saw > the bug on other servers with different generic configs > > it looks like it's related to cgroup local storage, for some reason > the storage deref returns NULL > > I'm bit lost in this code, so any help would be great ;-) Hi! I think the patch to blame is df1a2cb7c74b ("bpf/test_run: fix unkillable BPF_PROG_TEST_RUN"). Prior to it, we were running the test program in the preempt_disable() && rcu_read_lock() section: preempt_disable(); rcu_read_lock(); bpf_cgroup_storage_set(storage); ret = BPF_PROG_RUN(prog, ctx); rcu_read_unlock(); preempt_enable(); So, a percpu variable with a cgroup local storage pointer couldn't go away. After df1a2cb7c74b we can temporarily enable the preemption, so nothing prevents another program to call into bpf_cgroup_storage_set() on the same cpu. I guess it's exactly what happens here. One option to fix it is to make bpf_cgroup_storage_set() to return the old value, save it on a local variable and restore after the execution of the program. But I didn't follow closely the development of sleepable bpf programs, so I could easily miss something. Thanks! Roman > > thanks, > jirka > > > --- > ... > [ 382.324440] bpf_testmod: loading out-of-tree module taints kernel. > [ 382.330670] bpf_testmod: module verification failed: signature and/or required key missing - tainting kernel > [ 480.391667] perf: interrupt took too long (2540 > 2500), lowering kernel.perf_event_max_sample_rate to 78000 > [ 480.401730] perf: interrupt took too long (6860 > 6751), lowering kernel.perf_event_max_sample_rate to 29000 > [ 480.416172] perf: interrupt took too long (8602 > 8575), lowering kernel.perf_event_max_sample_rate to 23000 > [ 480.433053] BUG: kernel NULL pointer dereference, address: 0000000000000000 > [ 480.440014] #PF: supervisor read access in kernel mode > [ 480.445153] #PF: error_code(0x0000) - not-present page > [ 480.450294] PGD 8000000133a18067 P4D 8000000133a18067 PUD 10c019067 PMD 0 > [ 480.457164] Oops: 0000 [#1] PREEMPT SMP PTI > [ 480.461350] CPU: 6 PID: 16689 Comm: test_progs Tainted: G IOE 5.11.0+ #11 > [ 480.469263] Hardware name: Dell Inc. PowerEdge R440/08CYF7, BIOS 1.7.0 12/14/2018 > [ 480.476742] RIP: 0010:bpf_get_local_storage+0x13/0x50 > [ 480.481797] Code: e8 92 c5 8e 00 5d 89 c0 c3 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 00 0f 1f 44 00 00 83 7f 18 15 74 10 65 48 8b 05 6d c6 e2 7e <48> 8b 00 48 83 c0 10 c3 55 48 89 e5 53 65 48 8b 05 60 c6 e2 7e8 > [ 480.500540] RSP: 0018:ffffc90001bd3ce0 EFLAGS: 00010293 > [ 480.505766] RAX: 0000000000000000 RBX: 982a259500000000 RCX: 0000000000000018 > [ 480.512901] RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffff888149ccf000 > [ 480.520034] RBP: ffffc90001bd3d20 R08: ffffc90001bd3d04 R09: ffff888105121600 > [ 480.527164] R10: d3b9342000000000 R11: 000000000000025c R12: 0000000000000734 > [ 480.534299] R13: ffff888149ccc710 R14: 0000000000000000 R15: ffffc90000379048 > [ 480.541430] FS: 00007f8f2357b640(0000) GS:ffff8897e0980000(0000) knlGS:0000000000000000 > [ 480.549515] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > [ 480.555262] CR2: 0000000000000000 CR3: 000000014e826006 CR4: 00000000007706e0 > [ 480.562395] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 > [ 480.569527] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 > [ 480.576660] PKRU: 55555554 > [ 480.579372] Call Trace: > [ 480.581829] ? bpf_prog_c48154a736e5c014_bpf_sping_lock_test+0x2ba/0x860 > [ 480.588526] bpf_test_run+0x127/0x2b0 > [ 480.592192] ? __build_skb_around+0xb0/0xc0 > [ 480.596378] bpf_prog_test_run_skb+0x32f/0x6b0 > [ 480.600824] __do_sys_bpf+0xa94/0x2240 > [ 480.604577] ? debug_smp_processor_id+0x17/0x20 > [ 480.609107] ? __perf_event_task_sched_in+0x32/0x340 > [ 480.614077] __x64_sys_bpf+0x1a/0x20 > [ 480.617653] do_syscall_64+0x38/0x50 > [ 480.621233] entry_SYSCALL_64_after_hwframe+0x44/0xae > [ 480.626286] RIP: 0033:0x7f8f2467f55d > [ 480.629865] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d eb 78 0c 00 f7 d8 64 89 018 > [ 480.648611] RSP: 002b:00007f8f2357ad58 EFLAGS: 00000206 ORIG_RAX: 0000000000000141 > [ 480.656175] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f8f2467f55d > [ 480.663308] RDX: 0000000000000078 RSI: 00007f8f2357ad60 RDI: 000000000000000a > [ 480.670442] RBP: 00007f8f2357ae28 R08: 0000000000000000 R09: 0000000000000008 > [ 480.677574] R10: 0000000000000000 R11: 0000000000000206 R12: 00007f8f2357ae2c > [ 480.684707] R13: 00000000022df420 R14: 0000000000000000 R15: 00007f8f2357b640 > [ 480.691842] Modules linked in: bpf_testmod(OE) intel_rapl_msr intel_rapl_common x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm ipmi_ssif irqbypass rapl intel_cstate dell_smbios intel_uncore mei_] > [ 480.739134] CR2: 0000000000000000 > [ 480.742452] ---[ end trace 807177cbb5e3b3da ]--- > [ 480.752174] RIP: 0010:bpf_get_local_storage+0x13/0x50 > [ 480.757230] Code: e8 92 c5 8e 00 5d 89 c0 c3 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 00 0f 1f 44 00 00 83 7f 18 15 74 10 65 48 8b 05 6d c6 e2 7e <48> 8b 00 48 83 c0 10 c3 55 48 89 e5 53 65 48 8b 05 60 c6 e2 7e8 > [ 480.775976] RSP: 0018:ffffc90001bd3ce0 EFLAGS: 00010293 > [ 480.781202] RAX: 0000000000000000 RBX: 982a259500000000 RCX: 0000000000000018 > [ 480.788335] RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffff888149ccf000 > [ 480.795466] RBP: ffffc90001bd3d20 R08: ffffc90001bd3d04 R09: ffff888105121600 > [ 480.802598] R10: d3b9342000000000 R11: 000000000000025c R12: 0000000000000734 > [ 480.809730] R13: ffff888149ccc710 R14: 0000000000000000 R15: ffffc90000379048 > [ 480.816865] FS: 00007f8f2357b640(0000) GS:ffff8897e0980000(0000) knlGS:0000000000000000 > [ 480.824951] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > [ 480.830695] CR2: 0000000000000000 CR3: 000000014e826006 CR4: 00000000007706e0 > [ 480.837829] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 > [ 480.844961] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 > [ 480.852093] PKRU: 55555554 > ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: [BUG] hitting bug when running spinlock test 2021-03-05 20:38 ` Roman Gushchin @ 2021-03-05 21:10 ` Yonghong Song 2021-03-05 21:17 ` Stanislav Fomichev 2021-03-09 5:44 ` Yonghong Song 0 siblings, 2 replies; 9+ messages in thread From: Yonghong Song @ 2021-03-05 21:10 UTC (permalink / raw) To: Roman Gushchin, Jiri Olsa Cc: Alexei Starovoitov, Daniel Borkmann, YiFei Zhu, Andrii Nakryiko, netdev, bpf, Martin KaFai Lau, Song Liu, John Fastabend, KP Singh, Toke Høiland-Jørgensen, Yauheni Kaliuta, Jiri Benc, Hangbin Liu, Stanislav Fomichev On 3/5/21 12:38 PM, Roman Gushchin wrote: > On Thu, Mar 04, 2021 at 08:03:33PM +0100, Jiri Olsa wrote: >> hi, >> I'm getting attached BUG/crash when running in parralel selftests, like: >> >> while :; do ./test_progs -t spinlock; done >> while :; do ./test_progs ; done >> >> it's the latest bpf-next/master, I can send the .config if needed, >> but I don't think there's anything special about it, because I saw >> the bug on other servers with different generic configs >> >> it looks like it's related to cgroup local storage, for some reason >> the storage deref returns NULL >> >> I'm bit lost in this code, so any help would be great ;-) > > Hi! > > I think the patch to blame is df1a2cb7c74b ("bpf/test_run: fix unkillable BPF_PROG_TEST_RUN"). Thanks, Roman, I did some experiments and found the reason of NULL storage deref is because a tracing program (mostly like a kprobe) is run after bpf_cgroup_storage_set() is called but before bpf program calls bpf_get_local_storage(). Note that trace_call_bpf() macro BPF_PROG_RUN_ARRAY_CHECK does call bpf_cgroup_storage_set(). > Prior to it, we were running the test program in the preempt_disable() && rcu_read_lock() > section: > > preempt_disable(); > rcu_read_lock(); > bpf_cgroup_storage_set(storage); > ret = BPF_PROG_RUN(prog, ctx); > rcu_read_unlock(); > preempt_enable(); > > So, a percpu variable with a cgroup local storage pointer couldn't go away. I think even with using preempt_disable(), if the bpf program calls map lookup and there is a kprobe bpf on function htab_map_lookup_elem(), we will have the issue as BPF_PROG_RUN_ARRAY_CHECK will call bpf_cgroup_storage_set() too. I need to write a test case to confirm this though. > > After df1a2cb7c74b we can temporarily enable the preemption, so nothing prevents > another program to call into bpf_cgroup_storage_set() on the same cpu. > I guess it's exactly what happens here. It is. I confirmed. > > One option to fix it is to make bpf_cgroup_storage_set() to return the old value, > save it on a local variable and restore after the execution of the program. In this particular case, we are doing bpf_test_run, we explicitly allocate storage and call bpf_cgroup_storage_set() right before each BPF_PROG_RUN. > But I didn't follow closely the development of sleepable bpf programs, so I could > easily miss something. Yes, sleepable bpf program is another complication. I think we need a variable similar to bpf_prog_active, which should not nested bpf program execution for those bpf programs having local_storage map. Will try to craft some patch to facilitate the discussion. > > Thanks! > > Roman > >> >> thanks, >> jirka >> >> >> --- >> ... >> [ 382.324440] bpf_testmod: loading out-of-tree module taints kernel. >> [ 382.330670] bpf_testmod: module verification failed: signature and/or required key missing - tainting kernel >> [ 480.391667] perf: interrupt took too long (2540 > 2500), lowering kernel.perf_event_max_sample_rate to 78000 >> [ 480.401730] perf: interrupt took too long (6860 > 6751), lowering kernel.perf_event_max_sample_rate to 29000 >> [ 480.416172] perf: interrupt took too long (8602 > 8575), lowering kernel.perf_event_max_sample_rate to 23000 >> [ 480.433053] BUG: kernel NULL pointer dereference, address: 0000000000000000 >> [ 480.440014] #PF: supervisor read access in kernel mode >> [ 480.445153] #PF: error_code(0x0000) - not-present page >> [ 480.450294] PGD 8000000133a18067 P4D 8000000133a18067 PUD 10c019067 PMD 0 >> [ 480.457164] Oops: 0000 [#1] PREEMPT SMP PTI >> [ 480.461350] CPU: 6 PID: 16689 Comm: test_progs Tainted: G IOE 5.11.0+ #11 >> [ 480.469263] Hardware name: Dell Inc. PowerEdge R440/08CYF7, BIOS 1.7.0 12/14/2018 >> [ 480.476742] RIP: 0010:bpf_get_local_storage+0x13/0x50 >> [ 480.481797] Code: e8 92 c5 8e 00 5d 89 c0 c3 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 00 0f 1f 44 00 00 83 7f 18 15 74 10 65 48 8b 05 6d c6 e2 7e <48> 8b 00 48 83 c0 10 c3 55 48 89 e5 53 65 48 8b 05 60 c6 e2 7e8 >> [ 480.500540] RSP: 0018:ffffc90001bd3ce0 EFLAGS: 00010293 >> [ 480.505766] RAX: 0000000000000000 RBX: 982a259500000000 RCX: 0000000000000018 >> [ 480.512901] RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffff888149ccf000 >> [ 480.520034] RBP: ffffc90001bd3d20 R08: ffffc90001bd3d04 R09: ffff888105121600 >> [ 480.527164] R10: d3b9342000000000 R11: 000000000000025c R12: 0000000000000734 >> [ 480.534299] R13: ffff888149ccc710 R14: 0000000000000000 R15: ffffc90000379048 >> [ 480.541430] FS: 00007f8f2357b640(0000) GS:ffff8897e0980000(0000) knlGS:0000000000000000 >> [ 480.549515] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 >> [ 480.555262] CR2: 0000000000000000 CR3: 000000014e826006 CR4: 00000000007706e0 >> [ 480.562395] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 >> [ 480.569527] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 >> [ 480.576660] PKRU: 55555554 >> [ 480.579372] Call Trace: >> [ 480.581829] ? bpf_prog_c48154a736e5c014_bpf_sping_lock_test+0x2ba/0x860 >> [ 480.588526] bpf_test_run+0x127/0x2b0 >> [ 480.592192] ? __build_skb_around+0xb0/0xc0 >> [ 480.596378] bpf_prog_test_run_skb+0x32f/0x6b0 >> [ 480.600824] __do_sys_bpf+0xa94/0x2240 >> [ 480.604577] ? debug_smp_processor_id+0x17/0x20 >> [ 480.609107] ? __perf_event_task_sched_in+0x32/0x340 >> [ 480.614077] __x64_sys_bpf+0x1a/0x20 >> [ 480.617653] do_syscall_64+0x38/0x50 >> [ 480.621233] entry_SYSCALL_64_after_hwframe+0x44/0xae >> [ 480.626286] RIP: 0033:0x7f8f2467f55d >> [ 480.629865] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d eb 78 0c 00 f7 d8 64 89 018 >> [ 480.648611] RSP: 002b:00007f8f2357ad58 EFLAGS: 00000206 ORIG_RAX: 0000000000000141 >> [ 480.656175] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f8f2467f55d >> [ 480.663308] RDX: 0000000000000078 RSI: 00007f8f2357ad60 RDI: 000000000000000a >> [ 480.670442] RBP: 00007f8f2357ae28 R08: 0000000000000000 R09: 0000000000000008 >> [ 480.677574] R10: 0000000000000000 R11: 0000000000000206 R12: 00007f8f2357ae2c >> [ 480.684707] R13: 00000000022df420 R14: 0000000000000000 R15: 00007f8f2357b640 >> [ 480.691842] Modules linked in: bpf_testmod(OE) intel_rapl_msr intel_rapl_common x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm ipmi_ssif irqbypass rapl intel_cstate dell_smbios intel_uncore mei_] >> [ 480.739134] CR2: 0000000000000000 >> [ 480.742452] ---[ end trace 807177cbb5e3b3da ]--- >> [ 480.752174] RIP: 0010:bpf_get_local_storage+0x13/0x50 >> [ 480.757230] Code: e8 92 c5 8e 00 5d 89 c0 c3 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 00 0f 1f 44 00 00 83 7f 18 15 74 10 65 48 8b 05 6d c6 e2 7e <48> 8b 00 48 83 c0 10 c3 55 48 89 e5 53 65 48 8b 05 60 c6 e2 7e8 >> [ 480.775976] RSP: 0018:ffffc90001bd3ce0 EFLAGS: 00010293 >> [ 480.781202] RAX: 0000000000000000 RBX: 982a259500000000 RCX: 0000000000000018 >> [ 480.788335] RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffff888149ccf000 >> [ 480.795466] RBP: ffffc90001bd3d20 R08: ffffc90001bd3d04 R09: ffff888105121600 >> [ 480.802598] R10: d3b9342000000000 R11: 000000000000025c R12: 0000000000000734 >> [ 480.809730] R13: ffff888149ccc710 R14: 0000000000000000 R15: ffffc90000379048 >> [ 480.816865] FS: 00007f8f2357b640(0000) GS:ffff8897e0980000(0000) knlGS:0000000000000000 >> [ 480.824951] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 >> [ 480.830695] CR2: 0000000000000000 CR3: 000000014e826006 CR4: 00000000007706e0 >> [ 480.837829] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 >> [ 480.844961] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 >> [ 480.852093] PKRU: 55555554 >> ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: [BUG] hitting bug when running spinlock test 2021-03-05 21:10 ` Yonghong Song @ 2021-03-05 21:17 ` Stanislav Fomichev 2021-03-09 5:44 ` Yonghong Song 1 sibling, 0 replies; 9+ messages in thread From: Stanislav Fomichev @ 2021-03-05 21:17 UTC (permalink / raw) To: Yonghong Song Cc: Roman Gushchin, Jiri Olsa, Alexei Starovoitov, Daniel Borkmann, YiFei Zhu, Andrii Nakryiko, Netdev, bpf, Martin KaFai Lau, Song Liu, John Fastabend, KP Singh, Toke Høiland-Jørgensen, Yauheni Kaliuta, Jiri Benc, Hangbin Liu On Fri, Mar 5, 2021 at 1:10 PM Yonghong Song <yhs@fb.com> wrote: > > > > On 3/5/21 12:38 PM, Roman Gushchin wrote: > > On Thu, Mar 04, 2021 at 08:03:33PM +0100, Jiri Olsa wrote: > >> hi, > >> I'm getting attached BUG/crash when running in parralel selftests, like: > >> > >> while :; do ./test_progs -t spinlock; done > >> while :; do ./test_progs ; done > >> > >> it's the latest bpf-next/master, I can send the .config if needed, > >> but I don't think there's anything special about it, because I saw > >> the bug on other servers with different generic configs > >> > >> it looks like it's related to cgroup local storage, for some reason > >> the storage deref returns NULL > >> > >> I'm bit lost in this code, so any help would be great ;-) > > > > Hi! > > > > I think the patch to blame is df1a2cb7c74b ("bpf/test_run: fix unkillable BPF_PROG_TEST_RUN"). > > Thanks, Roman, I did some experiments and found the reason of NULL > storage deref is because a tracing program (mostly like a kprobe) is run > after bpf_cgroup_storage_set() is called but before bpf program calls > bpf_get_local_storage(). Note that trace_call_bpf() macro > BPF_PROG_RUN_ARRAY_CHECK does call bpf_cgroup_storage_set(). > > > Prior to it, we were running the test program in the preempt_disable() && rcu_read_lock() > > section: > > > > preempt_disable(); > > rcu_read_lock(); > > bpf_cgroup_storage_set(storage); > > ret = BPF_PROG_RUN(prog, ctx); > > rcu_read_unlock(); > > preempt_enable(); > > > > So, a percpu variable with a cgroup local storage pointer couldn't go away. > > I think even with using preempt_disable(), if the bpf program calls map > lookup and there is a kprobe bpf on function htab_map_lookup_elem(), we > will have the issue as BPF_PROG_RUN_ARRAY_CHECK will call > bpf_cgroup_storage_set() too. I need to write a test case to confirm > this though. > > > > > After df1a2cb7c74b we can temporarily enable the preemption, so nothing prevents > > another program to call into bpf_cgroup_storage_set() on the same cpu. > > I guess it's exactly what happens here. > > It is. I confirmed. > > > > > One option to fix it is to make bpf_cgroup_storage_set() to return the old value, > > save it on a local variable and restore after the execution of the program. > > In this particular case, we are doing bpf_test_run, we explicitly > allocate storage and call bpf_cgroup_storage_set() right before > each BPF_PROG_RUN. > > > But I didn't follow closely the development of sleepable bpf programs, so I could > > easily miss something. > > Yes, sleepable bpf program is another complication. I think we need a > variable similar to bpf_prog_active, which should not nested bpf program > execution for those bpf programs having local_storage map. > Will try to craft some patch to facilitate the discussion. Can we add a new argument to bpf_cgroup_storage_set to save existing per-cpu values (on the stack) such that we can restore them later, after BPF_PROG_RUN finishes? Is it too much overhead? > > > > > Thanks! > > > > Roman > > > >> > >> thanks, > >> jirka > >> > >> > >> --- > >> ... > >> [ 382.324440] bpf_testmod: loading out-of-tree module taints kernel. > >> [ 382.330670] bpf_testmod: module verification failed: signature and/or required key missing - tainting kernel > >> [ 480.391667] perf: interrupt took too long (2540 > 2500), lowering kernel.perf_event_max_sample_rate to 78000 > >> [ 480.401730] perf: interrupt took too long (6860 > 6751), lowering kernel.perf_event_max_sample_rate to 29000 > >> [ 480.416172] perf: interrupt took too long (8602 > 8575), lowering kernel.perf_event_max_sample_rate to 23000 > >> [ 480.433053] BUG: kernel NULL pointer dereference, address: 0000000000000000 > >> [ 480.440014] #PF: supervisor read access in kernel mode > >> [ 480.445153] #PF: error_code(0x0000) - not-present page > >> [ 480.450294] PGD 8000000133a18067 P4D 8000000133a18067 PUD 10c019067 PMD 0 > >> [ 480.457164] Oops: 0000 [#1] PREEMPT SMP PTI > >> [ 480.461350] CPU: 6 PID: 16689 Comm: test_progs Tainted: G IOE 5.11.0+ #11 > >> [ 480.469263] Hardware name: Dell Inc. PowerEdge R440/08CYF7, BIOS 1.7.0 12/14/2018 > >> [ 480.476742] RIP: 0010:bpf_get_local_storage+0x13/0x50 > >> [ 480.481797] Code: e8 92 c5 8e 00 5d 89 c0 c3 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 00 0f 1f 44 00 00 83 7f 18 15 74 10 65 48 8b 05 6d c6 e2 7e <48> 8b 00 48 83 c0 10 c3 55 48 89 e5 53 65 48 8b 05 60 c6 e2 7e8 > >> [ 480.500540] RSP: 0018:ffffc90001bd3ce0 EFLAGS: 00010293 > >> [ 480.505766] RAX: 0000000000000000 RBX: 982a259500000000 RCX: 0000000000000018 > >> [ 480.512901] RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffff888149ccf000 > >> [ 480.520034] RBP: ffffc90001bd3d20 R08: ffffc90001bd3d04 R09: ffff888105121600 > >> [ 480.527164] R10: d3b9342000000000 R11: 000000000000025c R12: 0000000000000734 > >> [ 480.534299] R13: ffff888149ccc710 R14: 0000000000000000 R15: ffffc90000379048 > >> [ 480.541430] FS: 00007f8f2357b640(0000) GS:ffff8897e0980000(0000) knlGS:0000000000000000 > >> [ 480.549515] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > >> [ 480.555262] CR2: 0000000000000000 CR3: 000000014e826006 CR4: 00000000007706e0 > >> [ 480.562395] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 > >> [ 480.569527] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 > >> [ 480.576660] PKRU: 55555554 > >> [ 480.579372] Call Trace: > >> [ 480.581829] ? bpf_prog_c48154a736e5c014_bpf_sping_lock_test+0x2ba/0x860 > >> [ 480.588526] bpf_test_run+0x127/0x2b0 > >> [ 480.592192] ? __build_skb_around+0xb0/0xc0 > >> [ 480.596378] bpf_prog_test_run_skb+0x32f/0x6b0 > >> [ 480.600824] __do_sys_bpf+0xa94/0x2240 > >> [ 480.604577] ? debug_smp_processor_id+0x17/0x20 > >> [ 480.609107] ? __perf_event_task_sched_in+0x32/0x340 > >> [ 480.614077] __x64_sys_bpf+0x1a/0x20 > >> [ 480.617653] do_syscall_64+0x38/0x50 > >> [ 480.621233] entry_SYSCALL_64_after_hwframe+0x44/0xae > >> [ 480.626286] RIP: 0033:0x7f8f2467f55d > >> [ 480.629865] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 90 f3 0f 1e fa 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d eb 78 0c 00 f7 d8 64 89 018 > >> [ 480.648611] RSP: 002b:00007f8f2357ad58 EFLAGS: 00000206 ORIG_RAX: 0000000000000141 > >> [ 480.656175] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f8f2467f55d > >> [ 480.663308] RDX: 0000000000000078 RSI: 00007f8f2357ad60 RDI: 000000000000000a > >> [ 480.670442] RBP: 00007f8f2357ae28 R08: 0000000000000000 R09: 0000000000000008 > >> [ 480.677574] R10: 0000000000000000 R11: 0000000000000206 R12: 00007f8f2357ae2c > >> [ 480.684707] R13: 00000000022df420 R14: 0000000000000000 R15: 00007f8f2357b640 > >> [ 480.691842] Modules linked in: bpf_testmod(OE) intel_rapl_msr intel_rapl_common x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm ipmi_ssif irqbypass rapl intel_cstate dell_smbios intel_uncore mei_] > >> [ 480.739134] CR2: 0000000000000000 > >> [ 480.742452] ---[ end trace 807177cbb5e3b3da ]--- > >> [ 480.752174] RIP: 0010:bpf_get_local_storage+0x13/0x50 > >> [ 480.757230] Code: e8 92 c5 8e 00 5d 89 c0 c3 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 00 0f 1f 44 00 00 83 7f 18 15 74 10 65 48 8b 05 6d c6 e2 7e <48> 8b 00 48 83 c0 10 c3 55 48 89 e5 53 65 48 8b 05 60 c6 e2 7e8 > >> [ 480.775976] RSP: 0018:ffffc90001bd3ce0 EFLAGS: 00010293 > >> [ 480.781202] RAX: 0000000000000000 RBX: 982a259500000000 RCX: 0000000000000018 > >> [ 480.788335] RDX: 0000000000000001 RSI: 0000000000000000 RDI: ffff888149ccf000 > >> [ 480.795466] RBP: ffffc90001bd3d20 R08: ffffc90001bd3d04 R09: ffff888105121600 > >> [ 480.802598] R10: d3b9342000000000 R11: 000000000000025c R12: 0000000000000734 > >> [ 480.809730] R13: ffff888149ccc710 R14: 0000000000000000 R15: ffffc90000379048 > >> [ 480.816865] FS: 00007f8f2357b640(0000) GS:ffff8897e0980000(0000) knlGS:0000000000000000 > >> [ 480.824951] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > >> [ 480.830695] CR2: 0000000000000000 CR3: 000000014e826006 CR4: 00000000007706e0 > >> [ 480.837829] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 > >> [ 480.844961] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 > >> [ 480.852093] PKRU: 55555554 > >> ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: [BUG] hitting bug when running spinlock test 2021-03-05 21:10 ` Yonghong Song 2021-03-05 21:17 ` Stanislav Fomichev @ 2021-03-09 5:44 ` Yonghong Song 2021-03-09 18:21 ` Roman Gushchin 1 sibling, 1 reply; 9+ messages in thread From: Yonghong Song @ 2021-03-09 5:44 UTC (permalink / raw) To: Roman Gushchin, Jiri Olsa Cc: Alexei Starovoitov, Daniel Borkmann, YiFei Zhu, Andrii Nakryiko, netdev, bpf, Martin KaFai Lau, Song Liu, John Fastabend, KP Singh, Toke Høiland-Jørgensen, Yauheni Kaliuta, Jiri Benc, Hangbin Liu, Stanislav Fomichev On 3/5/21 1:10 PM, Yonghong Song wrote: > > > On 3/5/21 12:38 PM, Roman Gushchin wrote: >> On Thu, Mar 04, 2021 at 08:03:33PM +0100, Jiri Olsa wrote: >>> hi, >>> I'm getting attached BUG/crash when running in parralel selftests, like: >>> >>> while :; do ./test_progs -t spinlock; done >>> while :; do ./test_progs ; done >>> >>> it's the latest bpf-next/master, I can send the .config if needed, >>> but I don't think there's anything special about it, because I saw >>> the bug on other servers with different generic configs >>> >>> it looks like it's related to cgroup local storage, for some reason >>> the storage deref returns NULL >>> >>> I'm bit lost in this code, so any help would be great ;-) >> >> Hi! >> >> I think the patch to blame is df1a2cb7c74b ("bpf/test_run: fix >> unkillable BPF_PROG_TEST_RUN"). > > Thanks, Roman, I did some experiments and found the reason of NULL > storage deref is because a tracing program (mostly like a kprobe) is run > after bpf_cgroup_storage_set() is called but before bpf program calls > bpf_get_local_storage(). Note that trace_call_bpf() macro > BPF_PROG_RUN_ARRAY_CHECK does call bpf_cgroup_storage_set(). > >> Prior to it, we were running the test program in the preempt_disable() >> && rcu_read_lock() >> section: >> >> preempt_disable(); >> rcu_read_lock(); >> bpf_cgroup_storage_set(storage); >> ret = BPF_PROG_RUN(prog, ctx); >> rcu_read_unlock(); >> preempt_enable(); >> >> So, a percpu variable with a cgroup local storage pointer couldn't go >> away. > > I think even with using preempt_disable(), if the bpf program calls map > lookup and there is a kprobe bpf on function htab_map_lookup_elem(), we > will have the issue as BPF_PROG_RUN_ARRAY_CHECK will call > bpf_cgroup_storage_set() too. I need to write a test case to confirm > this though. > >> >> After df1a2cb7c74b we can temporarily enable the preemption, so >> nothing prevents >> another program to call into bpf_cgroup_storage_set() on the same cpu. >> I guess it's exactly what happens here. > > It is. I confirmed. Actually, the failure is not due to breaking up preempt_disable(). Even with adding cond_resched(), bpf_cgroup_storage_set() still happens inside the preempt region. So it is okay. What I confirmed is that changing migration_{disable/enable} to preempt_{disable/enable} fixed the issue. So migration_{disable/enable} is the issue since any other process (and its bpf program) and preempted the current process/bpf program and run. Currently for each program, we will set the local storage before the program run and each program may access to multiple local storage maps. So we might need something similar sk_local_storage. Considering possibility of deep nested migration_{disable/enable}, the cgroup local storage has to be preserved in prog/map data structure and not as a percpu variable as it will be very hard to save and restore percpu virable content as migration can happen anywhere. I don't have concrete design yet. Just throw some idea here. BTW, I send a patch to prevent tracing programs to mess up with cgroup local storage: https://lore.kernel.org/bpf/20210309052638.400562-1-yhs@fb.com/T/#u we now all programs access cgroup local storage should be in process context and we don't need to worry about kprobe-induced percpu local storage access. > >> >> One option to fix it is to make bpf_cgroup_storage_set() to return the >> old value, >> save it on a local variable and restore after the execution of the >> program. > > In this particular case, we are doing bpf_test_run, we explicitly > allocate storage and call bpf_cgroup_storage_set() right before > each BPF_PROG_RUN. > >> But I didn't follow closely the development of sleepable bpf programs, >> so I could >> easily miss something. > > Yes, sleepable bpf program is another complication. I think we need a > variable similar to bpf_prog_active, which should not nested bpf program > execution for those bpf programs having local_storage map. > Will try to craft some patch to facilitate the discussion. > [...] ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: [BUG] hitting bug when running spinlock test 2021-03-09 5:44 ` Yonghong Song @ 2021-03-09 18:21 ` Roman Gushchin 2021-03-09 18:36 ` Yonghong Song 0 siblings, 1 reply; 9+ messages in thread From: Roman Gushchin @ 2021-03-09 18:21 UTC (permalink / raw) To: Yonghong Song Cc: Jiri Olsa, Alexei Starovoitov, Daniel Borkmann, YiFei Zhu, Andrii Nakryiko, netdev, bpf, Martin KaFai Lau, Song Liu, John Fastabend, KP Singh, Toke Høiland-Jørgensen, Yauheni Kaliuta, Jiri Benc, Hangbin Liu, Stanislav Fomichev On Mon, Mar 08, 2021 at 09:44:08PM -0800, Yonghong Song wrote: > > > On 3/5/21 1:10 PM, Yonghong Song wrote: > > > > > > On 3/5/21 12:38 PM, Roman Gushchin wrote: > > > On Thu, Mar 04, 2021 at 08:03:33PM +0100, Jiri Olsa wrote: > > > > hi, > > > > I'm getting attached BUG/crash when running in parralel selftests, like: > > > > > > > > while :; do ./test_progs -t spinlock; done > > > > while :; do ./test_progs ; done > > > > > > > > it's the latest bpf-next/master, I can send the .config if needed, > > > > but I don't think there's anything special about it, because I saw > > > > the bug on other servers with different generic configs > > > > > > > > it looks like it's related to cgroup local storage, for some reason > > > > the storage deref returns NULL > > > > > > > > I'm bit lost in this code, so any help would be great ;-) > > > > > > Hi! > > > > > > I think the patch to blame is df1a2cb7c74b ("bpf/test_run: fix > > > unkillable BPF_PROG_TEST_RUN"). > > > > Thanks, Roman, I did some experiments and found the reason of NULL > > storage deref is because a tracing program (mostly like a kprobe) is run > > after bpf_cgroup_storage_set() is called but before bpf program calls > > bpf_get_local_storage(). Note that trace_call_bpf() macro > > BPF_PROG_RUN_ARRAY_CHECK does call bpf_cgroup_storage_set(). > > > > > Prior to it, we were running the test program in the > > > preempt_disable() && rcu_read_lock() > > > section: > > > > > > preempt_disable(); > > > rcu_read_lock(); > > > bpf_cgroup_storage_set(storage); > > > ret = BPF_PROG_RUN(prog, ctx); > > > rcu_read_unlock(); > > > preempt_enable(); > > > > > > So, a percpu variable with a cgroup local storage pointer couldn't > > > go away. > > > > I think even with using preempt_disable(), if the bpf program calls map > > lookup and there is a kprobe bpf on function htab_map_lookup_elem(), we > > will have the issue as BPF_PROG_RUN_ARRAY_CHECK will call > > bpf_cgroup_storage_set() too. I need to write a test case to confirm > > this though. > > > > > > > > After df1a2cb7c74b we can temporarily enable the preemption, so > > > nothing prevents > > > another program to call into bpf_cgroup_storage_set() on the same cpu. > > > I guess it's exactly what happens here. > > > > It is. I confirmed. > > Actually, the failure is not due to breaking up preempt_disable(). Even with > adding cond_resched(), bpf_cgroup_storage_set() still happens > inside the preempt region. So it is okay. What I confirmed is that > changing migration_{disable/enable} to preempt_{disable/enable} fixed > the issue. Hm, how so? If preemption is enabled, another task/bpf program can start executing on the same cpu and set their cgroup storage. I guess it's harder to reproduce or it will result in the (bpf map) memory corruption instead of a panic, but I don't think it's safe. > > So migration_{disable/enable} is the issue since any other process (and its > bpf program) and preempted the current process/bpf program and run. Oh, I didn't know about the preempt_{disable/enable}/migration_{disable/enable} change. It's definitely not safe from a cgroup local storage perspective. > Currently for each program, we will set the local storage before the > program run and each program may access to multiple local storage > maps. So we might need something similar sk_local_storage. > Considering possibility of deep nested migration_{disable/enable}, > the cgroup local storage has to be preserved in prog/map data > structure and not as a percpu variable as it will be very hard > to save and restore percpu virable content as migration can > happen anywhere. I don't have concrete design yet. Just throw some > idea here. Initially I thought about saving this pointer on stack, but then we need some sort of gcc/assembly magic to get this pointer from the stack outside of the current scope. At that time we didn't have sleepable programs, so the percpu approach looked simpler and more reliable. Maybe it's time to review it. > > BTW, I send a patch to prevent tracing programs to mess up > with cgroup local storage: > https://lore.kernel.org/bpf/20210309052638.400562-1-yhs@fb.com/T/#u > we now all programs access cgroup local storage should be in > process context and we don't need to worry about kprobe-induced > percpu local storage access. Thank you! My only issue is that the commit log looks like an optimization (like we're calling for set_cgroup_storage() for no good reason), where if I understand it correctly, it prevents some class of problems. Thanks! > > > > > > > > > One option to fix it is to make bpf_cgroup_storage_set() to return > > > the old value, > > > save it on a local variable and restore after the execution of the > > > program. > > > > In this particular case, we are doing bpf_test_run, we explicitly > > allocate storage and call bpf_cgroup_storage_set() right before > > each BPF_PROG_RUN. > > > > > But I didn't follow closely the development of sleepable bpf > > > programs, so I could > > > easily miss something. > > > > Yes, sleepable bpf program is another complication. I think we need a > > variable similar to bpf_prog_active, which should not nested bpf program > > execution for those bpf programs having local_storage map. > > Will try to craft some patch to facilitate the discussion. > > > [...] ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: [BUG] hitting bug when running spinlock test 2021-03-09 18:21 ` Roman Gushchin @ 2021-03-09 18:36 ` Yonghong Song 2021-03-09 19:25 ` Roman Gushchin 0 siblings, 1 reply; 9+ messages in thread From: Yonghong Song @ 2021-03-09 18:36 UTC (permalink / raw) To: Roman Gushchin Cc: Jiri Olsa, Alexei Starovoitov, Daniel Borkmann, YiFei Zhu, Andrii Nakryiko, netdev, bpf, Martin KaFai Lau, Song Liu, John Fastabend, KP Singh, Toke Høiland-Jørgensen, Yauheni Kaliuta, Jiri Benc, Hangbin Liu, Stanislav Fomichev On 3/9/21 10:21 AM, Roman Gushchin wrote: > On Mon, Mar 08, 2021 at 09:44:08PM -0800, Yonghong Song wrote: >> >> >> On 3/5/21 1:10 PM, Yonghong Song wrote: >>> >>> >>> On 3/5/21 12:38 PM, Roman Gushchin wrote: >>>> On Thu, Mar 04, 2021 at 08:03:33PM +0100, Jiri Olsa wrote: >>>>> hi, >>>>> I'm getting attached BUG/crash when running in parralel selftests, like: >>>>> >>>>> while :; do ./test_progs -t spinlock; done >>>>> while :; do ./test_progs ; done >>>>> >>>>> it's the latest bpf-next/master, I can send the .config if needed, >>>>> but I don't think there's anything special about it, because I saw >>>>> the bug on other servers with different generic configs >>>>> >>>>> it looks like it's related to cgroup local storage, for some reason >>>>> the storage deref returns NULL >>>>> >>>>> I'm bit lost in this code, so any help would be great ;-) >>>> >>>> Hi! >>>> >>>> I think the patch to blame is df1a2cb7c74b ("bpf/test_run: fix >>>> unkillable BPF_PROG_TEST_RUN"). >>> >>> Thanks, Roman, I did some experiments and found the reason of NULL >>> storage deref is because a tracing program (mostly like a kprobe) is run >>> after bpf_cgroup_storage_set() is called but before bpf program calls >>> bpf_get_local_storage(). Note that trace_call_bpf() macro >>> BPF_PROG_RUN_ARRAY_CHECK does call bpf_cgroup_storage_set(). >>> >>>> Prior to it, we were running the test program in the >>>> preempt_disable() && rcu_read_lock() >>>> section: >>>> >>>> preempt_disable(); >>>> rcu_read_lock(); >>>> bpf_cgroup_storage_set(storage); >>>> ret = BPF_PROG_RUN(prog, ctx); >>>> rcu_read_unlock(); >>>> preempt_enable(); >>>> >>>> So, a percpu variable with a cgroup local storage pointer couldn't >>>> go away. >>> >>> I think even with using preempt_disable(), if the bpf program calls map >>> lookup and there is a kprobe bpf on function htab_map_lookup_elem(), we >>> will have the issue as BPF_PROG_RUN_ARRAY_CHECK will call >>> bpf_cgroup_storage_set() too. I need to write a test case to confirm >>> this though. >>> >>>> >>>> After df1a2cb7c74b we can temporarily enable the preemption, so >>>> nothing prevents >>>> another program to call into bpf_cgroup_storage_set() on the same cpu. >>>> I guess it's exactly what happens here. >>> >>> It is. I confirmed. >> >> Actually, the failure is not due to breaking up preempt_disable(). Even with >> adding cond_resched(), bpf_cgroup_storage_set() still happens >> inside the preempt region. So it is okay. What I confirmed is that >> changing migration_{disable/enable} to preempt_{disable/enable} fixed >> the issue. > > Hm, how so? If preemption is enabled, another task/bpf program can start > executing on the same cpu and set their cgroup storage. I guess it's harder > to reproduce or it will result in the (bpf map) memory corruption instead > of a panic, but I don't think it's safe. The code has been refactored recently. The following is the code right before refactoring to make it easy to understand: rcu_read_lock(); migrate_disable(); time_start = ktime_get_ns(); for (i = 0; i < repeat; i++) { bpf_cgroup_storage_set(storage); if (xdp) *retval = bpf_prog_run_xdp(prog, ctx); else *retval = BPF_PROG_RUN(prog, ctx); if (signal_pending(current)) { ret = -EINTR; break; } if (need_resched()) { time_spent += ktime_get_ns() - time_start; migrate_enable(); rcu_read_unlock(); cond_resched(); rcu_read_lock(); migrate_disable(); time_start = ktime_get_ns(); } } time_spent += ktime_get_ns() - time_start; migrate_enable(); rcu_read_unlock(); bpf_cgroup_storage_set() is called inside migration_disable/enable(). Previously it is called inside preempt_disable/enable(), so it should be fine. > >> >> So migration_{disable/enable} is the issue since any other process (and its >> bpf program) and preempted the current process/bpf program and run. > > Oh, I didn't know about the preempt_{disable/enable}/migration_{disable/enable} > change. It's definitely not safe from a cgroup local storage perspective. > >> Currently for each program, we will set the local storage before the >> program run and each program may access to multiple local storage >> maps. So we might need something similar sk_local_storage. >> Considering possibility of deep nested migration_{disable/enable}, >> the cgroup local storage has to be preserved in prog/map data >> structure and not as a percpu variable as it will be very hard >> to save and restore percpu virable content as migration can >> happen anywhere. I don't have concrete design yet. Just throw some >> idea here. > > Initially I thought about saving this pointer on stack, but then we need > some sort of gcc/assembly magic to get this pointer from the stack outside > of the current scope. At that time we didn't have sleepable programs, > so the percpu approach looked simpler and more reliable. Maybe it's time > to review it. Indeed this is the time. > >> >> BTW, I send a patch to prevent tracing programs to mess up >> with cgroup local storage: >> https://lore.kernel.org/bpf/20210309052638.400562-1-yhs@fb.com/T/#u >> we now all programs access cgroup local storage should be in >> process context and we don't need to worry about kprobe-induced >> percpu local storage access. > > Thank you! My only issue is that the commit log looks like an optimization > (like we're calling for set_cgroup_storage() for no good reason), where if > I understand it correctly, it prevents some class of problems. Yes, it prevents real problems as well. The reason I did not say it is because the patch does not really fix fundamental issue. But it does prevent some issues. Let me reword the commit message. > > Thanks! > >> >>> >>>> >>>> One option to fix it is to make bpf_cgroup_storage_set() to return >>>> the old value, >>>> save it on a local variable and restore after the execution of the >>>> program. >>> >>> In this particular case, we are doing bpf_test_run, we explicitly >>> allocate storage and call bpf_cgroup_storage_set() right before >>> each BPF_PROG_RUN. >>> >>>> But I didn't follow closely the development of sleepable bpf >>>> programs, so I could >>>> easily miss something. >>> >>> Yes, sleepable bpf program is another complication. I think we need a >>> variable similar to bpf_prog_active, which should not nested bpf program >>> execution for those bpf programs having local_storage map. >>> Will try to craft some patch to facilitate the discussion. >>> >> [...] ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: [BUG] hitting bug when running spinlock test 2021-03-09 18:36 ` Yonghong Song @ 2021-03-09 19:25 ` Roman Gushchin 0 siblings, 0 replies; 9+ messages in thread From: Roman Gushchin @ 2021-03-09 19:25 UTC (permalink / raw) To: Yonghong Song Cc: Jiri Olsa, Alexei Starovoitov, Daniel Borkmann, YiFei Zhu, Andrii Nakryiko, netdev, bpf, Martin KaFai Lau, Song Liu, John Fastabend, KP Singh, Toke Høiland-Jørgensen, Yauheni Kaliuta, Jiri Benc, Hangbin Liu, Stanislav Fomichev On Tue, Mar 09, 2021 at 10:36:06AM -0800, Yonghong Song wrote: > > > On 3/9/21 10:21 AM, Roman Gushchin wrote: > > On Mon, Mar 08, 2021 at 09:44:08PM -0800, Yonghong Song wrote: > > > > > > > > > On 3/5/21 1:10 PM, Yonghong Song wrote: > > > > > > > > > > > > On 3/5/21 12:38 PM, Roman Gushchin wrote: > > > > > On Thu, Mar 04, 2021 at 08:03:33PM +0100, Jiri Olsa wrote: > > > > > > hi, > > > > > > I'm getting attached BUG/crash when running in parralel selftests, like: > > > > > > > > > > > > while :; do ./test_progs -t spinlock; done > > > > > > while :; do ./test_progs ; done > > > > > > > > > > > > it's the latest bpf-next/master, I can send the .config if needed, > > > > > > but I don't think there's anything special about it, because I saw > > > > > > the bug on other servers with different generic configs > > > > > > > > > > > > it looks like it's related to cgroup local storage, for some reason > > > > > > the storage deref returns NULL > > > > > > > > > > > > I'm bit lost in this code, so any help would be great ;-) > > > > > > > > > > Hi! > > > > > > > > > > I think the patch to blame is df1a2cb7c74b ("bpf/test_run: fix > > > > > unkillable BPF_PROG_TEST_RUN"). > > > > > > > > Thanks, Roman, I did some experiments and found the reason of NULL > > > > storage deref is because a tracing program (mostly like a kprobe) is run > > > > after bpf_cgroup_storage_set() is called but before bpf program calls > > > > bpf_get_local_storage(). Note that trace_call_bpf() macro > > > > BPF_PROG_RUN_ARRAY_CHECK does call bpf_cgroup_storage_set(). > > > > > > > > > Prior to it, we were running the test program in the > > > > > preempt_disable() && rcu_read_lock() > > > > > section: > > > > > > > > > > preempt_disable(); > > > > > rcu_read_lock(); > > > > > bpf_cgroup_storage_set(storage); > > > > > ret = BPF_PROG_RUN(prog, ctx); > > > > > rcu_read_unlock(); > > > > > preempt_enable(); > > > > > > > > > > So, a percpu variable with a cgroup local storage pointer couldn't > > > > > go away. > > > > > > > > I think even with using preempt_disable(), if the bpf program calls map > > > > lookup and there is a kprobe bpf on function htab_map_lookup_elem(), we > > > > will have the issue as BPF_PROG_RUN_ARRAY_CHECK will call > > > > bpf_cgroup_storage_set() too. I need to write a test case to confirm > > > > this though. > > > > > > > > > > > > > > After df1a2cb7c74b we can temporarily enable the preemption, so > > > > > nothing prevents > > > > > another program to call into bpf_cgroup_storage_set() on the same cpu. > > > > > I guess it's exactly what happens here. > > > > > > > > It is. I confirmed. > > > > > > Actually, the failure is not due to breaking up preempt_disable(). Even with > > > adding cond_resched(), bpf_cgroup_storage_set() still happens > > > inside the preempt region. So it is okay. What I confirmed is that > > > changing migration_{disable/enable} to preempt_{disable/enable} fixed > > > the issue. > > > > Hm, how so? If preemption is enabled, another task/bpf program can start > > executing on the same cpu and set their cgroup storage. I guess it's harder > > to reproduce or it will result in the (bpf map) memory corruption instead > > of a panic, but I don't think it's safe. > > The code has been refactored recently. The following is the code right > before refactoring to make it easy to understand: > > rcu_read_lock(); > migrate_disable(); > time_start = ktime_get_ns(); > for (i = 0; i < repeat; i++) { > bpf_cgroup_storage_set(storage); > > if (xdp) > *retval = bpf_prog_run_xdp(prog, ctx); > else > *retval = BPF_PROG_RUN(prog, ctx); > > if (signal_pending(current)) { > ret = -EINTR; > break; > } > > if (need_resched()) { > time_spent += ktime_get_ns() - time_start; > migrate_enable(); > rcu_read_unlock(); > > cond_resched(); > > rcu_read_lock(); > migrate_disable(); > time_start = ktime_get_ns(); > } > } > time_spent += ktime_get_ns() - time_start; > migrate_enable(); > rcu_read_unlock(); > > bpf_cgroup_storage_set() is called inside migration_disable/enable(). > Previously it is called inside preempt_disable/enable(), so it should be > fine. Ah, gotcha, thank you for the explanation! > > > > > > > > > So migration_{disable/enable} is the issue since any other process (and its > > > bpf program) and preempted the current process/bpf program and run. > > > > Oh, I didn't know about the preempt_{disable/enable}/migration_{disable/enable} > > change. It's definitely not safe from a cgroup local storage perspective. > > > > > Currently for each program, we will set the local storage before the > > > program run and each program may access to multiple local storage > > > maps. So we might need something similar sk_local_storage. > > > Considering possibility of deep nested migration_{disable/enable}, > > > the cgroup local storage has to be preserved in prog/map data > > > structure and not as a percpu variable as it will be very hard > > > to save and restore percpu virable content as migration can > > > happen anywhere. I don't have concrete design yet. Just throw some > > > idea here. > > > > Initially I thought about saving this pointer on stack, but then we need > > some sort of gcc/assembly magic to get this pointer from the stack outside > > of the current scope. At that time we didn't have sleepable programs, > > so the percpu approach looked simpler and more reliable. Maybe it's time > > to review it. > > Indeed this is the time. > > > > > > > > > BTW, I send a patch to prevent tracing programs to mess up > > > with cgroup local storage: > > > https://lore.kernel.org/bpf/20210309052638.400562-1-yhs@fb.com/T/#u > > > we now all programs access cgroup local storage should be in > > > process context and we don't need to worry about kprobe-induced > > > percpu local storage access. > > > > Thank you! My only issue is that the commit log looks like an optimization > > (like we're calling for set_cgroup_storage() for no good reason), where if > > I understand it correctly, it prevents some class of problems. > > Yes, it prevents real problems as well. The reason I did not say it is > because the patch does not really fix fundamental issue. But it does > prevent some issues. Let me reword the commit message. Thank you! ^ permalink raw reply [flat|nested] 9+ messages in thread
end of thread, other threads:[~2021-03-09 19:26 UTC | newest] Thread overview: 9+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2021-03-04 19:03 [BUG] hitting bug when running spinlock test Jiri Olsa 2021-03-05 4:08 ` Yonghong Song 2021-03-05 20:38 ` Roman Gushchin 2021-03-05 21:10 ` Yonghong Song 2021-03-05 21:17 ` Stanislav Fomichev 2021-03-09 5:44 ` Yonghong Song 2021-03-09 18:21 ` Roman Gushchin 2021-03-09 18:36 ` Yonghong Song 2021-03-09 19:25 ` Roman Gushchin
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).