[BUG] hitting bug when running spinlock test

9 messages, 4 authors, 2021-03-09 · open the first message on its own page

[BUG] hitting bug when running spinlock test

From: Jiri Olsa <hidden>
Date: 2021-03-04 19:06:10

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

Re: [BUG] hitting bug when running spinlock test

From: Yonghong Song <hidden>
Date: 2021-03-05 04:08:48


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

Re: [BUG] hitting bug when running spinlock test

From: Roman Gushchin <hidden>
Date: 2021-03-05 20:40:34

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

Re: [BUG] hitting bug when running spinlock test

From: Yonghong Song <hidden>
Date: 2021-03-05 21:11:42


On 3/5/21 12:38 PM, Roman Gushchin wrote:
On Thu, Mar 04, 2021 at 08:03:33PM +0100, Jiri Olsa wrote:
quoted
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
quoted
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

Re: [BUG] hitting bug when running spinlock test

From: Stanislav Fomichev <hidden>
Date: 2021-03-05 21:18:05

On Fri, Mar 5, 2021 at 1:10 PM Yonghong Song [off-list ref] wrote:


On 3/5/21 12:38 PM, Roman Gushchin wrote:
quoted
On Thu, Mar 04, 2021 at 08:03:33PM +0100, Jiri Olsa wrote:
quoted
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().
quoted
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.
quoted
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.
quoted
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.
quoted
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?

quoted
Thanks!

Roman
quoted
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

Re: [BUG] hitting bug when running spinlock test

From: Yonghong Song <hidden>
Date: 2021-03-09 05:45:38


On 3/5/21 1:10 PM, Yonghong Song wrote:

On 3/5/21 12:38 PM, Roman Gushchin wrote:
quoted
On Thu, Mar 04, 2021 at 08:03:33PM +0100, Jiri Olsa wrote:
quoted
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().
quoted
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.
quoted
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.
quoted
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.
quoted
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.
[...]

Re: [BUG] hitting bug when running spinlock test

From: Roman Gushchin <hidden>
Date: 2021-03-09 18:22:24

On Mon, Mar 08, 2021 at 09:44:08PM -0800, Yonghong Song wrote:

On 3/5/21 1:10 PM, Yonghong Song wrote:
quoted

On 3/5/21 12:38 PM, Roman Gushchin wrote:
quoted
On Thu, Mar 04, 2021 at 08:03:33PM +0100, Jiri Olsa wrote:
quoted
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().
quoted
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.
quoted
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!
quoted
quoted
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.
quoted
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.
[...]

Re: [BUG] hitting bug when running spinlock test

From: Yonghong Song <hidden>
Date: 2021-03-09 18:39:56


On 3/9/21 10:21 AM, Roman Gushchin wrote:
On Mon, Mar 08, 2021 at 09:44:08PM -0800, Yonghong Song wrote:
quoted

On 3/5/21 1:10 PM, Yonghong Song wrote:
quoted

On 3/5/21 12:38 PM, Roman Gushchin wrote:
quoted
On Thu, Mar 04, 2021 at 08:03:33PM +0100, Jiri Olsa wrote:
quoted
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().
quoted
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.
quoted
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.
quoted
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.
quoted
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.
quoted
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!
quoted
quoted
quoted
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.
quoted
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.
[...]

Re: [BUG] hitting bug when running spinlock test

From: Roman Gushchin <hidden>
Date: 2021-03-09 19:26:23

On Tue, Mar 09, 2021 at 10:36:06AM -0800, Yonghong Song wrote:

On 3/9/21 10:21 AM, Roman Gushchin wrote:
quoted
On Mon, Mar 08, 2021 at 09:44:08PM -0800, Yonghong Song wrote:
quoted

On 3/5/21 1:10 PM, Yonghong Song wrote:
quoted

On 3/5/21 12:38 PM, Roman Gushchin wrote:
quoted
On Thu, Mar 04, 2021 at 08:03:33PM +0100, Jiri Olsa wrote:
quoted
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().
quoted
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.
quoted
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!
quoted
quoted
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.
quoted
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.
quoted
quoted
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!
Keyboard shortcuts
hback out one level
jnext message in thread
kprevious message in thread
ldrill in
Escclose help / fold thread tree
?toggle this help