On 8/29/20 3:38 PM, Alexei Starovoitov wrote:

On 8/29/20 3:13 PM, Yonghong Song wrote:

quoted

When running selftest, I hit the following kernel warning:

[  250.871267] ============================================
[  250.871902] WARNING: possible recursive locking detected
[  250.872561] 5.9.0-rc1+ #830 Not tainted
[  250.873166] --------------------------------------------
[  250.873991] true/2053 is trying to acquire lock:
[  250.874715] ffff8fc1f9cd2068 (&mm->mmap_lock#2){++++}-{3:3}, at: 
__might_fault+0x3e/0x90
[  250.875943]
[  250.875943] but task is already holding lock:
[  250.876688] ffff8fc1f9cd2068 (&mm->mmap_lock#2){++++}-{3:3}, at: 
do_mprotect_pkey+0xb5/0x2f0
[  250.877978]
[  250.877978] other info that might help us debug this:
[  250.878797]  Possible unsafe locking scenario:
[  250.878797]
[  250.879708]        CPU0
[  250.880095]        ----
[  250.880482]   lock(&mm->mmap_lock#2);
[  250.881063]   lock(&mm->mmap_lock#2);
[  250.881645]
[  250.881645]  *** DEADLOCK ***
[  250.881645]
[  250.882559]  May be due to missing lock nesting notation
[  250.882559]
[  250.883613] 2 locks held by true/2053:
[  250.884194]  #0: ffff8fc1f9cd2068 (&mm->mmap_lock#2){++++}-{3:3}, 
at: do_mprotect_pkey+0xb5/0x2f0
[  250.885558]  #1: ffffffffbc47b8a0 
(rcu_read_lock_trace){....}-{0:0}, at: 
__bpf_prog_enter_sleepable+0x0/0x40
[  250.887062]
[  250.887062] stack backtrace:
[  250.887583] CPU: 1 PID: 2053 Comm: true Not tainted 5.9.0-rc1+ #830
[  250.888546] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), 
BIOS 1.9.3-1.el7.centos 04/01/2014
[  250.889896] Call Trace:
[  250.890222]  dump_stack+0x78/0xa0
[  250.890644]  __lock_acquire.cold.74+0x209/0x2e3
[  250.891350]  lock_acquire+0xba/0x380
[  250.891919]  ? __might_fault+0x3e/0x90
[  250.892510]  ? __lock_acquire+0x639/0x20c0
[  250.893150]  __might_fault+0x68/0x90
[  250.893717]  ? __might_fault+0x3e/0x90
[  250.894325]  _copy_from_user+0x1e/0xa0
[  250.894946]  bpf_copy_from_user+0x22/0x50
[  250.895581]  bpf_prog_3717002769f30998_test_int_hook+0x76/0x60c
[  250.896446]  ? __bpf_prog_enter_sleepable+0x3c/0x40
[  250.897207]  ? __bpf_prog_exit+0xa0/0xa0
[  250.897819]  bpf_trampoline_18669+0x29/0x1000
[  250.898476]  bpf_lsm_file_mprotect+0x5/0x10
[  250.899133]  security_file_mprotect+0x32/0x50
[  250.899816]  do_mprotect_pkey+0x18a/0x2f0
[  250.900472]  __x64_sys_mprotect+0x1b/0x20
[  250.901107]  do_syscall_64+0x33/0x40
[  250.901670]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[  250.902450] RIP: 0033:0x7fd95c141ef7
[  250.903014] Code: ff 66 90 b8 0b 00 00 00 0f 05 48 3d 01 f0 ff ff 
73 01 c3 48 8d 0d 21 c2 2
0 00 f7 d8 89 01 48 83 c8 ff c3 b8 0a 00 00 00 0f 05 <48> 3d 01 f0 ff 
ff 73 01 c3 48 8d 0d 01
c2 20 00 f7 d8 89 01 48 83
[  250.905732] RSP: 002b:00007ffd4c291fe8 EFLAGS: 00000246 ORIG_RAX: 
000000000000000a
[  250.906773] RAX: ffffffffffffffda RBX: 0000000000000005 RCX: 
00007fd95c141ef7
[  250.907866] RDX: 0000000000000000 RSI: 00000000001ff000 RDI: 
00007fd95bf20000
[  250.908906] RBP: 00007ffd4c292320 R08: 0000000000000000 R09: 
0000000000000000
[  250.909915] R10: 00007ffd4c291ff0 R11: 0000000000000246 R12: 
00007fd95c341000
[  250.910919] R13: 00007ffd4c292408 R14: 0000000000000002 R15: 
0000000000000801

Could this be an real issue here?

do_mprotect_pkey() gets a lock of current->mm->mmap_lock
before calling security_file_mprotect(bpf_lsm_file_mprotect).
Later on, when do _copy_to_user(), page fault may happen
and current->mm->mmap_lock might be acquired again and may
have a deadlock here?

Hmm. It does sound like dead_lock.
But I don't understand why I don't see this splat.
I have
LOCKDEP=y
DEBUG_ATOMIC_SLEEP=y
LOCK_DEBUGGING_SUPPORT=y
KASAN=y
in my .config and don't see it :(
Could pls send me your .config?

The config file is attached. In my environment, the warning is only
printed out during the first run of `./test_progs -t lsm`. All later
runs did not have this warning.

I'll analyze further.
Thanks for the reporting!