possible deadlock in perf_trace

possible deadlock in perf_trace_destroy
Status: auto-closed as invalid on 2019/03/09 03:11
Reported-by: syzbot+@syzkaller.appspotmail.com
First crash: 973d, last: 973d

similar bugs (5):
Kernel	Title	Repro	Fix bisect	Count	Last	Reported	Patched	Status
upstream	possible deadlock in perf_trace_destroy (3)			12	876d	1005d	0/22	auto-closed as invalid on 2019/06/14 09:18
upstream	possible deadlock in perf_trace_destroy (2)	C		2006	1194d	1280d	6/22	fixed on 2018/04/24 21:47
android-414	possible deadlock in perf_trace_destroy (2)			1	763d	757d	0/1	auto-closed as invalid on 2019/10/05 09:33
upstream	possible deadlock in perf_trace_destroy	C		525	1302d	1286d	0/22	closed as invalid on 2017/11/01 19:39
linux-4.14	possible deadlock in perf_trace_destroy	C	inconclusive	829	345d	756d	0/1	upstream: reported C repro on 2019/04/15 13:38

Sample crash report:

======================================================
WARNING: possible circular locking dependency detected
4.14.68+ #4 Not tainted
------------------------------------------------------
syz-executor1/24168 is trying to acquire lock:
 (event_mutex){+.+.}, at: [<ffffffff8bd61ef3>] perf_trace_destroy+0x23/0x100 kernel/trace/trace_event_perf.c:234

but task is already holding lock:
 (&mm->mmap_sem){++++}, at: [<ffffffff8be9000f>] vm_mmap_pgoff+0x14f/0x1d0 mm/util.c:331

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #2 (&mm->mmap_sem){++++}:
       __might_fault+0x137/0x1b0 mm/memory.c:4538
       _copy_to_user+0x27/0xc0 lib/usercopy.c:25
       copy_to_user include/linux/uaccess.h:155 [inline]
       filldir+0x192/0x340 fs/readdir.c:197
       dir_emit_dot include/linux/fs.h:3380 [inline]
       dir_emit_dots include/linux/fs.h:3391 [inline]
       dcache_readdir+0x12f/0x5d0 fs/libfs.c:192
       iterate_dir+0x19f/0x5e0 fs/readdir.c:52
       SYSC_getdents fs/readdir.c:232 [inline]
       SyS_getdents+0x146/0x270 fs/readdir.c:213
       do_syscall_64+0x19b/0x4b0 arch/x86/entry/common.c:289
       entry_SYSCALL_64_after_hwframe+0x42/0xb7

-> #1 (&sb->s_type->i_mutex_key#6){++++}:
       down_write+0x34/0x90 kernel/locking/rwsem.c:54
       inode_lock include/linux/fs.h:713 [inline]
       start_creating.part.2+0x4c/0x160 fs/tracefs/inode.c:335
       start_creating fs/tracefs/inode.c:324 [inline]
       tracefs_create_file+0x75/0x450 fs/tracefs/inode.c:400
       create_event_toplevel_files+0x2d/0x150 kernel/trace/trace_events.c:2912
       early_event_add_tracer kernel/trace/trace_events.c:2999 [inline]
       event_trace_init+0x30a/0x4e3 kernel/trace/trace_events.c:3164
       do_one_initcall+0x99/0x1aa init/main.c:826
       do_initcall_level init/main.c:892 [inline]
       do_initcalls init/main.c:900 [inline]
       do_basic_setup init/main.c:918 [inline]
       kernel_init_freeable+0x2df/0x39f init/main.c:1073
       kernel_init+0xc/0x157 init/main.c:1000
       ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:402

-> #0 (event_mutex){+.+.}:
       lock_acquire+0x10f/0x380 kernel/locking/lockdep.c:3991
       __mutex_lock_common kernel/locking/mutex.c:756 [inline]
       __mutex_lock+0xf5/0x1480 kernel/locking/mutex.c:893
       perf_trace_destroy+0x23/0x100 kernel/trace/trace_event_perf.c:234
       _free_event+0x293/0xb00 kernel/events/core.c:4237
       put_event+0x20/0x30 kernel/events/core.c:4323
       perf_mmap_close+0x3f2/0xc40 kernel/events/core.c:5271
       remove_vma+0xaa/0x150 mm/mmap.c:172
       remove_vma_list mm/mmap.c:2516 [inline]
       do_munmap+0x8f0/0xd60 mm/mmap.c:2757
       mmap_region+0x164/0xfb0 mm/mmap.c:1672
       do_mmap+0x551/0xb80 mm/mmap.c:1509
       do_mmap_pgoff include/linux/mm.h:2167 [inline]
       vm_mmap_pgoff+0x180/0x1d0 mm/util.c:333
       SYSC_mmap_pgoff mm/mmap.c:1559 [inline]
       SyS_mmap_pgoff+0xf8/0x1a0 mm/mmap.c:1517
       do_syscall_64+0x19b/0x4b0 arch/x86/entry/common.c:289
       entry_SYSCALL_64_after_hwframe+0x42/0xb7

other info that might help us debug this:

Chain exists of:
  event_mutex --> &sb->s_type->i_mutex_key#6 --> &mm->mmap_sem

 Possible unsafe locking scenario:

       CPU0                    CPU1
       ----                    ----
  lock(&mm->mmap_sem);
                               lock(&sb->s_type->i_mutex_key#6);
                               lock(&mm->mmap_sem);
  lock(event_mutex);

 *** DEADLOCK ***

1 lock held by syz-executor1/24168:
 #0:  (&mm->mmap_sem){++++}, at: [<ffffffff8be9000f>] vm_mmap_pgoff+0x14f/0x1d0 mm/util.c:331

stack backtrace:
CPU: 1 PID: 24168 Comm: syz-executor1 Not tainted 4.14.68+ #4
Call Trace:
 __dump_stack lib/dump_stack.c:17 [inline]
 dump_stack+0xb9/0x11b lib/dump_stack.c:53
 print_circular_bug.isra.18.cold.43+0x2d3/0x40c kernel/locking/lockdep.c:1258
 check_prev_add kernel/locking/lockdep.c:1901 [inline]
 check_prevs_add kernel/locking/lockdep.c:2018 [inline]
 validate_chain kernel/locking/lockdep.c:2460 [inline]
 __lock_acquire+0x2ff9/0x4320 kernel/locking/lockdep.c:3487
 lock_acquire+0x10f/0x380 kernel/locking/lockdep.c:3991
 __mutex_lock_common kernel/locking/mutex.c:756 [inline]
 __mutex_lock+0xf5/0x1480 kernel/locking/mutex.c:893
 perf_trace_destroy+0x23/0x100 kernel/trace/trace_event_perf.c:234
 _free_event+0x293/0xb00 kernel/events/core.c:4237
 put_event+0x20/0x30 kernel/events/core.c:4323
 perf_mmap_close+0x3f2/0xc40 kernel/events/core.c:5271
 remove_vma+0xaa/0x150 mm/mmap.c:172
 remove_vma_list mm/mmap.c:2516 [inline]
 do_munmap+0x8f0/0xd60 mm/mmap.c:2757
 mmap_region+0x164/0xfb0 mm/mmap.c:1672
 do_mmap+0x551/0xb80 mm/mmap.c:1509
 do_mmap_pgoff include/linux/mm.h:2167 [inline]
 vm_mmap_pgoff+0x180/0x1d0 mm/util.c:333
 SYSC_mmap_pgoff mm/mmap.c:1559 [inline]
 SyS_mmap_pgoff+0xf8/0x1a0 mm/mmap.c:1517
 do_syscall_64+0x19b/0x4b0 arch/x86/entry/common.c:289
 entry_SYSCALL_64_after_hwframe+0x42/0xb7
RIP: 0033:0x457099
RSP: 002b:00007f1117048c78 EFLAGS: 00000246 ORIG_RAX: 0000000000000009
RAX: ffffffffffffffda RBX: 00007f11170496d4 RCX: 0000000000457099
RDX: 0000000000000000 RSI: 0000000000002000 RDI: 00000000201c0000
RBP: 00000000009300a0 R08: 000000000000000c R09: 0000000000000000
R10: 0000000000004011 R11: 0000000000000246 R12: 00000000ffffffff
R13: 00000000004d3168 R14: 00000000004c8161 R15: 0000000000000000
netlink: 4 bytes leftover after parsing attributes in process `syz-executor0'.
netlink: 4 bytes leftover after parsing attributes in process `syz-executor0'.
input: syz1 as /devices/virtual/input/input47
uinput: write device info first
EXT4-fs (loop2): feature flags set on rev 0 fs, running e2fsck is recommended
EXT4-fs (loop2): bad geometry: block count 65280 exceeds size of device (2 blocks)
EXT4-fs warning (device sda1): ext4_group_add:1607: No reserved GDT blocks, can't resize
sock: sock_set_timeout: `syz-executor3' (pid 24817) tries to set negative timeout
sock: sock_set_timeout: `syz-executor3' (pid 24829) tries to set negative timeout
SELinux: unrecognized netlink message: protocol=0 nlmsg_type=1548 sclass=netlink_route_socket pig=24851 comm=syz-executor1
SELinux: unrecognized netlink message: protocol=0 nlmsg_type=1548 sclass=netlink_route_socket pig=24861 comm=syz-executor1
SELinux: unrecognized netlink message: protocol=0 nlmsg_type=25955 sclass=netlink_route_socket pig=25031 comm=syz-executor2
SELinux: unrecognized netlink message: protocol=0 nlmsg_type=25955 sclass=netlink_route_socket pig=25039 comm=syz-executor2
SELinux:  policydb magic number 0x30343030 does not match expected magic number 0xf97cff8c
SELinux: failed to load policy
SELinux:  policydb magic number 0x30343030 does not match expected magic number 0xf97cff8c
SELinux: failed to load policy
netlink: 8 bytes leftover after parsing attributes in process `syz-executor3'.
netlink: 8 bytes leftover after parsing attributes in process `syz-executor3'.

Crashes (1):
Manager	Time	Kernel	Commit	Syzkaller	Config	Log	Report	Syz repro	C repro	VM info	Title
ci-android-414-kasan-gce-root	2018/09/10 03:10	android-4.14	b859aa7d	6b5120a4	.config	log	report