syzbot


possible deadlock in perf_event_for_each_child

Status: auto-closed as invalid on 2019/12/15 20:17
Reported-by: syzbot+f38c077282be87991690@syzkaller.appspotmail.com
First crash: 2235d, last: 1922d
Similar bugs (2)
Kernel Title Repro Cause bisect Fix bisect Count Last Reported Patched Status
upstream possible deadlock in perf_event_for_each_child perf 135 2485d 2494d 0/28 auto-closed as invalid on 2019/02/22 10:22
linux-4.14 possible deadlock in perf_event_for_each_child C 1482 631d 2048d 0/1 upstream: reported C repro on 2019/04/14 09:58

Sample crash report:
======================================================
WARNING: possible circular locking dependency detected
4.14.139+ #34 Not tainted
------------------------------------------------------
syz-executor.3/7353 is trying to acquire lock:
 (&event->child_mutex){+.+.}, at: [<00000000b378cbb6>] perf_event_for_each_child+0x82/0x150 kernel/events/core.c:4687

but task is already holding lock:
 (&cpuctx_mutex){+.+.}, at: [<000000006e51dfa1>] perf_event_ctx_lock_nested+0x15a/0x2d0 kernel/events/core.c:1240

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #8 (&cpuctx_mutex){+.+.}:
       __mutex_lock_common kernel/locking/mutex.c:756 [inline]
       __mutex_lock+0xf7/0x13e0 kernel/locking/mutex.c:893
       perf_event_init_cpu+0xa8/0x150 kernel/events/core.c:11231
       perf_event_init+0x289/0x2c5 kernel/events/core.c:11278
       start_kernel+0x43d/0x74a init/main.c:621
       secondary_startup_64+0xa5/0xb0 arch/x86/kernel/head_64.S:240

-> #7 (pmus_lock){+.+.}:
       __mutex_lock_common kernel/locking/mutex.c:756 [inline]
       __mutex_lock+0xf7/0x13e0 kernel/locking/mutex.c:893
       perf_event_init_cpu+0x2c/0x150 kernel/events/core.c:11225
       cpuhp_invoke_callback+0x207/0x1a30 kernel/cpu.c:184
       cpuhp_up_callbacks kernel/cpu.c:572 [inline]
       _cpu_up+0x20b/0x500 kernel/cpu.c:1134
       do_cpu_up+0x64/0x120 kernel/cpu.c:1169
       smp_init+0x142/0x154 kernel/smp.c:578
       kernel_init_freeable+0x196/0x3b0 init/main.c:1067
       kernel_init+0xd/0x164 init/main.c:999
       ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:404

-> #6 (cpu_hotplug_lock.rw_sem){++++}:
       percpu_down_read_preempt_disable include/linux/percpu-rwsem.h:36 [inline]
       percpu_down_read include/linux/percpu-rwsem.h:59 [inline]
       cpus_read_lock+0x39/0xc0 kernel/cpu.c:295
       get_online_cpus include/linux/cpu.h:140 [inline]
       lru_add_drain_all+0xa/0x20 mm/swap.c:729
       shmem_wait_for_pins mm/shmem.c:2732 [inline]
       shmem_add_seals+0x633/0x11b0 mm/shmem.c:2841
       shmem_fcntl+0xea/0x120 mm/shmem.c:2876
       do_fcntl+0x5c8/0xd20 fs/fcntl.c:421
       SYSC_fcntl fs/fcntl.c:463 [inline]
       SyS_fcntl+0xc6/0x100 fs/fcntl.c:448
       do_syscall_64+0x19b/0x520 arch/x86/entry/common.c:292
       entry_SYSCALL_64_after_hwframe+0x42/0xb7

-> #5 (&sb->s_type->i_mutex_key#10){+.+.}:
       down_write+0x34/0x90 kernel/locking/rwsem.c:54
       inode_lock include/linux/fs.h:718 [inline]
       shmem_fallocate+0x150/0xae0 mm/shmem.c:2902
       ashmem_shrink_scan drivers/staging/android/ashmem.c:453 [inline]
       ashmem_shrink_scan+0x1ca/0x4f0 drivers/staging/android/ashmem.c:437
       ashmem_ioctl+0x2b4/0xd20 drivers/staging/android/ashmem.c:795
       vfs_ioctl fs/ioctl.c:46 [inline]
       file_ioctl fs/ioctl.c:500 [inline]
       do_vfs_ioctl+0xabe/0x1040 fs/ioctl.c:684
       SYSC_ioctl fs/ioctl.c:701 [inline]
       SyS_ioctl+0x7f/0xb0 fs/ioctl.c:692
       do_syscall_64+0x19b/0x520 arch/x86/entry/common.c:292
       entry_SYSCALL_64_after_hwframe+0x42/0xb7

-> #4 (ashmem_mutex){+.+.}:
       __mutex_lock_common kernel/locking/mutex.c:756 [inline]
       __mutex_lock+0xf7/0x13e0 kernel/locking/mutex.c:893
       ashmem_mmap+0x4c/0x450 drivers/staging/android/ashmem.c:369
       call_mmap include/linux/fs.h:1793 [inline]
       mmap_region+0x7d9/0xfb0 mm/mmap.c:1732
       do_mmap+0x548/0xb80 mm/mmap.c:1510
       do_mmap_pgoff include/linux/mm.h:2209 [inline]
       vm_mmap_pgoff+0x177/0x1c0 mm/util.c:333
       SYSC_mmap_pgoff mm/mmap.c:1560 [inline]
       SyS_mmap_pgoff+0xf4/0x1b0 mm/mmap.c:1518
       do_syscall_64+0x19b/0x520 arch/x86/entry/common.c:292
       entry_SYSCALL_64_after_hwframe+0x42/0xb7

-> #3 (&mm->mmap_sem){++++}:
       __might_fault mm/memory.c:4584 [inline]
       __might_fault+0x137/0x1b0 mm/memory.c:4569
       _copy_to_user+0x27/0xd0 lib/usercopy.c:25
       copy_to_user include/linux/uaccess.h:155 [inline]
       filldir+0x198/0x2f0 fs/readdir.c:197
       dir_emit_dot include/linux/fs.h:3379 [inline]
       dir_emit_dots include/linux/fs.h:3390 [inline]
       dcache_readdir+0x123/0x5c0 fs/libfs.c:192
       iterate_dir+0x1a5/0x5f0 fs/readdir.c:52
       SYSC_getdents fs/readdir.c:232 [inline]
       SyS_getdents+0x145/0x290 fs/readdir.c:213
       do_syscall_64+0x19b/0x520 arch/x86/entry/common.c:292
       entry_SYSCALL_64_after_hwframe+0x42/0xb7

-> #2 (&sb->s_type->i_mutex_key#5){++++}:
       down_write+0x34/0x90 kernel/locking/rwsem.c:54
       inode_lock include/linux/fs.h:718 [inline]
       start_creating.part.0+0x4c/0x150 fs/tracefs/inode.c:335
       start_creating fs/tracefs/inode.c:324 [inline]
       tracefs_create_file+0x74/0x450 fs/tracefs/inode.c:400
       create_event_toplevel_files+0x2d/0x150 kernel/trace/trace_events.c:2909
       early_event_add_tracer kernel/trace/trace_events.c:2996 [inline]
       event_trace_init+0x312/0x4ec kernel/trace/trace_events.c:3161
       do_one_initcall+0xa0/0x1ac init/main.c:825
       do_initcall_level init/main.c:891 [inline]
       do_initcalls init/main.c:899 [inline]
       do_basic_setup init/main.c:917 [inline]
       kernel_init_freeable+0x2ef/0x3b0 init/main.c:1074
       kernel_init+0xd/0x164 init/main.c:999
       ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:404

-> #1 (event_mutex){+.+.}:
       __mutex_lock_common kernel/locking/mutex.c:756 [inline]
       __mutex_lock+0xf7/0x13e0 kernel/locking/mutex.c:893
       perf_trace_destroy+0x23/0x100 kernel/trace/trace_event_perf.c:234
       _free_event+0x293/0xbb0 kernel/events/core.c:4243
       free_event+0x42/0xa0 kernel/events/core.c:4270
       perf_event_release_kernel+0x35c/0x880 kernel/events/core.c:4414
       perf_release+0x33/0x40 kernel/events/core.c:4440
       __fput+0x25e/0x710 fs/file_table.c:210
       task_work_run+0x125/0x1a0 kernel/task_work.c:113
       exit_task_work include/linux/task_work.h:22 [inline]
       do_exit+0x9cb/0x2a20 kernel/exit.c:875
       do_group_exit+0x100/0x2e0 kernel/exit.c:978
       SYSC_exit_group kernel/exit.c:989 [inline]
       SyS_exit_group+0x19/0x20 kernel/exit.c:987
       do_syscall_64+0x19b/0x520 arch/x86/entry/common.c:292
       entry_SYSCALL_64_after_hwframe+0x42/0xb7

-> #0 (&event->child_mutex){+.+.}:
       lock_acquire+0x12b/0x360 kernel/locking/lockdep.c:3991
       __mutex_lock_common kernel/locking/mutex.c:756 [inline]
       __mutex_lock+0xf7/0x13e0 kernel/locking/mutex.c:893
       perf_event_for_each_child+0x82/0x150 kernel/events/core.c:4687
       _perf_ioctl kernel/events/core.c:4871 [inline]
       perf_ioctl+0x53e/0x1bb0 kernel/events/core.c:4883
       vfs_ioctl fs/ioctl.c:46 [inline]
       file_ioctl fs/ioctl.c:500 [inline]
       do_vfs_ioctl+0xabe/0x1040 fs/ioctl.c:684
       SYSC_ioctl fs/ioctl.c:701 [inline]
       SyS_ioctl+0x7f/0xb0 fs/ioctl.c:692
       do_syscall_64+0x19b/0x520 arch/x86/entry/common.c:292
       entry_SYSCALL_64_after_hwframe+0x42/0xb7

other info that might help us debug this:

Chain exists of:
  &event->child_mutex --> pmus_lock --> &cpuctx_mutex

 Possible unsafe locking scenario:

       CPU0                    CPU1
       ----                    ----
  lock(&cpuctx_mutex);
                               lock(pmus_lock);
                               lock(&cpuctx_mutex);
  lock(&event->child_mutex);

 *** DEADLOCK ***

1 lock held by syz-executor.3/7353:
 #0:  (&cpuctx_mutex){+.+.}, at: [<000000006e51dfa1>] perf_event_ctx_lock_nested+0x15a/0x2d0 kernel/events/core.c:1240

stack backtrace:
CPU: 1 PID: 7353 Comm: syz-executor.3 Not tainted 4.14.139+ #34
Call Trace:
 __dump_stack lib/dump_stack.c:17 [inline]
 dump_stack+0xca/0x134 lib/dump_stack.c:53
 print_circular_bug.isra.0.cold+0x2dc/0x425 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+0x2f5f/0x4320 kernel/locking/lockdep.c:3487
 lock_acquire+0x12b/0x360 kernel/locking/lockdep.c:3991
 __mutex_lock_common kernel/locking/mutex.c:756 [inline]
 __mutex_lock+0xf7/0x13e0 kernel/locking/mutex.c:893
 perf_event_for_each_child+0x82/0x150 kernel/events/core.c:4687
 _perf_ioctl kernel/events/core.c:4871 [inline]
 perf_ioctl+0x53e/0x1bb0 kernel/events/core.c:4883
 vfs_ioctl fs/ioctl.c:46 [inline]
 file_ioctl fs/ioctl.c:500 [inline]
 do_vfs_ioctl+0xabe/0x1040 fs/ioctl.c:684
 SYSC_ioctl fs/ioctl.c:701 [inline]
 SyS_ioctl+0x7f/0xb0 fs/ioctl.c:692
 do_syscall_64+0x19b/0x520 arch/x86/entry/common.c:292
 entry_SYSCALL_64_after_hwframe+0x42/0xb7
RIP: 0033:0x459829
RSP: 002b:00007fe6bdbf5c78 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 0000000000459829
RDX: 0000000000000000 RSI: 0000000000002403 RDI: 0000000000000004
RBP: 000000000075bf20 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00007fe6bdbf66d4
R13: 00000000004c324a R14: 00000000004d69c0 R15: 00000000ffffffff
kauditd_printk_skb: 45 callbacks suppressed
audit: type=1400 audit(1566072969.041:90152): avc:  denied  { map } for  pid=7391 comm="syz-executor.4" path="/root/syzkaller-testdir812875195/syzkaller.q5LNvq/758/bus" dev="sda1" ino=16771 scontext=unconfined_u:system_r:insmod_t:s0-s0:c0.c1023 tcontext=unconfined_u:object_r:user_home_t:s0 tclass=file permissive=1
audit: type=1400 audit(1566072969.481:90153): avc:  denied  { map } for  pid=7418 comm="syz-executor.4" path="/root/syzkaller-testdir812875195/syzkaller.q5LNvq/759/bus" dev="sda1" ino=16806 scontext=unconfined_u:system_r:insmod_t:s0-s0:c0.c1023 tcontext=unconfined_u:object_r:user_home_t:s0 tclass=file permissive=1
audit: type=1400 audit(1566072969.861:90154): avc:  denied  { map } for  pid=7434 comm="syz-executor.4" path="/dev/loop0" dev="sda1" ino=2661 scontext=unconfined_u:system_r:insmod_t:s0-s0:c0.c1023 tcontext=system_u:object_r:file_t:s0 tclass=blk_file permissive=1
audit: type=1400 audit(1566072970.201:90155): avc:  denied  { map } for  pid=7454 comm="modprobe" path="/bin/kmod" dev="sda1" ino=1440 scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:file_t:s0 tclass=file permissive=1
audit: type=1400 audit(1566072970.201:90156): avc:  denied  { map } for  pid=7454 comm="modprobe" path="/bin/kmod" dev="sda1" ino=1440 scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:file_t:s0 tclass=file permissive=1
audit: type=1400 audit(1566072970.201:90157): avc:  denied  { map } for  pid=7454 comm="modprobe" path="/lib/x86_64-linux-gnu/ld-2.13.so" dev="sda1" ino=2668 scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:file_t:s0 tclass=file permissive=1
audit: type=1400 audit(1566072970.201:90158): avc:  denied  { map } for  pid=7454 comm="modprobe" path="/lib/x86_64-linux-gnu/ld-2.13.so" dev="sda1" ino=2668 scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:file_t:s0 tclass=file permissive=1
audit: type=1400 audit(1566072970.211:90159): avc:  denied  { map } for  pid=7454 comm="modprobe" path="/etc/ld.so.cache" dev="sda1" ino=2503 scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:file_t:s0 tclass=file permissive=1
audit: type=1400 audit(1566072970.211:90160): avc:  denied  { map } for  pid=7454 comm="modprobe" path="/lib/x86_64-linux-gnu/libkmod.so.2.1.3" dev="sda1" ino=2811 scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:file_t:s0 tclass=file permissive=1
audit: type=1400 audit(1566072970.211:90161): avc:  denied  { map } for  pid=7454 comm="modprobe" path="/lib/x86_64-linux-gnu/libkmod.so.2.1.3" dev="sda1" ino=2811 scontext=system_u:system_r:kernel_t:s0 tcontext=system_u:object_r:file_t:s0 tclass=file permissive=1

Crashes (9):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2019/08/17 20:16 android-4.14 5d8bfdf81cde 55bf8926 .config console log report ci-android-414-kasan-gce-root
2019/04/08 08:00 android-4.14 171fc237b3cb c34fde03 .config console log report ci-android-414-kasan-gce-root
2019/04/07 20:21 android-4.14 171fc237b3cb c34fde03 .config console log report ci-android-414-kasan-gce-root
2019/01/30 13:51 android-4.14 63d1657d00e0 aa432daf .config console log report ci-android-414-kasan-gce-root
2018/12/27 18:10 android-4.14 815e34f802d8 43cf01dd .config console log report ci-android-414-kasan-gce-root
2018/12/27 10:06 android-4.14 815e34f802d8 e747ec98 .config console log report ci-android-414-kasan-gce-root
2018/12/15 07:13 android-4.14 4ee7197c44f6 7624ddd6 .config console log report ci-android-414-kasan-gce-root
2018/11/29 08:29 android-4.14 9ff6ab2fbc00 4b6d14f2 .config console log report ci-android-414-kasan-gce-root
2018/10/09 10:45 android-4.14 d33692e8014d 8b311eaf .config console log report ci-android-414-kasan-gce-root
* Struck through repros no longer work on HEAD.