====================================================== WARNING: possible circular locking dependency detected 4.13.0-rc6-next-20170825+ #9 Not tainted ------------------------------------------------------ kworker/3:1/803 is trying to acquire lock: ((&w->work)){+.+.}, at: [] process_one_work+0xb2c/0x1be0 kernel/workqueue.c:2094 but now in release context of a crosslock acquired at the following: ((complete)&rcu.completion){+.+.}, at: [] __synchronize_srcu+0x1b5/0x250 kernel/rcu/srcutree.c:898 which lock already depends on the new lock. the existing dependency chain (in reverse order) is: -> #2 ((complete)&rcu.completion){+.+.}: check_prevs_add kernel/locking/lockdep.c:2020 [inline] validate_chain kernel/locking/lockdep.c:2469 [inline] __lock_acquire+0x3286/0x4620 kernel/locking/lockdep.c:3498 lock_acquire+0x1d5/0x580 kernel/locking/lockdep.c:4002 complete_acquire include/linux/completion.h:39 [inline] __wait_for_common kernel/sched/completion.c:108 [inline] wait_for_common kernel/sched/completion.c:122 [inline] wait_for_completion+0xc8/0x770 kernel/sched/completion.c:143 __synchronize_srcu+0x1b5/0x250 kernel/rcu/srcutree.c:898 synchronize_srcu_expedited kernel/rcu/srcutree.c:923 [inline] synchronize_srcu+0x1a3/0x560 kernel/rcu/srcutree.c:974 quarantine_remove_cache+0xd7/0xf0 mm/kasan/quarantine.c:327 kasan_cache_shrink+0x9/0x10 mm/kasan/kasan.c:380 kmem_cache_shrink+0x15/0x30 mm/slab_common.c:857 acpi_os_purge_cache+0x15/0x20 drivers/acpi/osl.c:1560 acpi_purge_cached_objects+0x38/0xc9 drivers/acpi/acpica/utxface.c:271 acpi_initialize_objects+0xc5/0x112 drivers/acpi/acpica/utxfinit.c:302 acpi_bus_init drivers/acpi/bus.c:1131 [inline] acpi_init+0x23c/0x8e6 drivers/acpi/bus.c:1220 do_one_initcall+0x9e/0x330 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+0x469/0x521 init/main.c:1066 kernel_init+0x13/0x172 init/main.c:993 ret_from_fork+0x2a/0x40 arch/x86/entry/entry_64.S:431 -> #1 (cpu_hotplug_lock.rw_sem){++++}: check_prevs_add kernel/locking/lockdep.c:2020 [inline] validate_chain kernel/locking/lockdep.c:2469 [inline] __lock_acquire+0x3286/0x4620 kernel/locking/lockdep.c:3498 lock_acquire+0x1d5/0x580 kernel/locking/lockdep.c:4002 percpu_down_read_preempt_disable include/linux/percpu-rwsem.h:35 [inline] percpu_down_read include/linux/percpu-rwsem.h:58 [inline] cpus_read_lock+0x42/0x90 kernel/cpu.c:218 __static_key_slow_dec kernel/jump_label.c:213 [inline] static_key_slow_dec+0x4a/0x90 kernel/jump_label.c:228 once_deferred+0x5c/0x90 lib/once.c:17 process_one_work+0xbfd/0x1be0 kernel/workqueue.c:2098 worker_thread+0x223/0x1860 kernel/workqueue.c:2233 kthread+0x39c/0x470 kernel/kthread.c:231 ret_from_fork+0x2a/0x40 arch/x86/entry/entry_64.S:431 -> #0 ((&w->work)){+.+.}: process_one_work+0xba5/0x1be0 kernel/workqueue.c:2095 worker_thread+0x223/0x1860 kernel/workqueue.c:2233 kthread+0x39c/0x470 kernel/kthread.c:231 ret_from_fork+0x2a/0x40 arch/x86/entry/entry_64.S:431 0xffffffffffffffff other info that might help us debug this: Chain exists of: (&w->work) --> cpu_hotplug_lock.rw_sem --> (complete)&rcu.completion Possible unsafe locking scenario by crosslock: CPU0 CPU1 ---- ---- lock(cpu_hotplug_lock.rw_sem); lock((complete)&rcu.completion); lock((&w->work)); unlock((complete)&rcu.completion); *** DEADLOCK *** 3 locks held by kworker/3:1/803: #0: ("events_power_efficient"){.+.+}, at: [] __write_once_size include/linux/compiler.h:305 [inline] #0: ("events_power_efficient"){.+.+}, at: [] atomic64_set arch/x86/include/asm/atomic64_64.h:33 [inline] #0: ("events_power_efficient"){.+.+}, at: [] atomic_long_set include/asm-generic/atomic-long.h:56 [inline] #0: ("events_power_efficient"){.+.+}, at: [] set_work_data kernel/workqueue.c:617 [inline] #0: ("events_power_efficient"){.+.+}, at: [] set_work_pool_and_clear_pending kernel/workqueue.c:644 [inline] #0: ("events_power_efficient"){.+.+}, at: [] process_one_work+0xad4/0x1be0 kernel/workqueue.c:2090 #1: ((&(&sdp->work)->work)){+.+.}, at: [] process_one_work+0xb2c/0x1be0 kernel/workqueue.c:2094 #2: (&x->wait#5){....}, at: [] complete+0x18/0x80 kernel/sched/completion.c:34 stack backtrace: CPU: 3 PID: 803 Comm: kworker/3:1 Not tainted 4.13.0-rc6-next-20170825+ #9 Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011 Workqueue: events_power_efficient srcu_invoke_callbacks Call Trace: __dump_stack lib/dump_stack.c:16 [inline] dump_stack+0x194/0x257 lib/dump_stack.c:52 print_circular_bug+0x503/0x710 kernel/locking/lockdep.c:1259 check_prev_add+0x865/0x1520 kernel/locking/lockdep.c:1894 commit_xhlock kernel/locking/lockdep.c:5002 [inline] commit_xhlocks kernel/locking/lockdep.c:5046 [inline] lock_commit_crosslock+0xe73/0x1d10 kernel/locking/lockdep.c:5085 complete_release_commit include/linux/completion.h:49 [inline] complete+0x24/0x80 kernel/sched/completion.c:39 wakeme_after_rcu+0xd/0x10 kernel/rcu/update.c:376 srcu_invoke_callbacks+0x280/0x4d0 kernel/rcu/srcutree.c:1161 process_one_work+0xbfd/0x1be0 kernel/workqueue.c:2098 worker_thread+0x223/0x1860 kernel/workqueue.c:2233 kthread+0x39c/0x470 kernel/kthread.c:231 ret_from_fork+0x2a/0x40 arch/x86/entry/entry_64.S:431 netlink: 5 bytes leftover after parsing attributes in process `syz-executor1'. netlink: 5 bytes leftover after parsing attributes in process `syz-executor1'. netlink: 11 bytes leftover after parsing attributes in process `syz-executor5'. netlink: 11 bytes leftover after parsing attributes in process `syz-executor5'. netlink: 11 bytes leftover after parsing attributes in process `syz-executor5'. netlink: 11 bytes leftover after parsing attributes in process `syz-executor5'. netlink: 11 bytes leftover after parsing attributes in process `syz-executor5'. netlink: 11 bytes leftover after parsing attributes in process `syz-executor5'. syz-executor5 uses obsolete (PF_INET,SOCK_PACKET) sg_write: data in/out 196574/112 bytes for SCSI command 0x8-- guessing data in; program syz-executor0 not setting count and/or reply_len properly sg_write: data in/out 196574/112 bytes for SCSI command 0x8-- guessing data in; program syz-executor0 not setting count and/or reply_len properly device lo entered promiscuous mode TCP: request_sock_TCP: Possible SYN flooding on port 20008. Sending cookies. Check SNMP counters. netlink: 1 bytes leftover after parsing attributes in process `syz-executor6'. netlink: 1 bytes leftover after parsing attributes in process `syz-executor6'. IPv6: NLM_F_REPLACE set, but no existing node found! raw_sendmsg: syz-executor5 forgot to set AF_INET. Fix it! rpcbind: RPC call returned error 22 rpcbind: RPC call returned error 22 sg_write: data in/out 393180/6 bytes for SCSI command 0x27-- guessing data in; program syz-executor7 not setting count and/or reply_len properly sit0: Invalid MTU 16777220 requested, hw max 65508 QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl audit: type=1326 audit(1503700726.614:2): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=4028 comm="syz-executor2" exe="/syz-executor2" sig=31 arch=c000003e syscall=202 compat=0 ip=0x446749 code=0xffff0000 audit: type=1326 audit(1503700726.626:3): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=4037 comm="syz-executor1" exe="/syz-executor1" sig=31 arch=c000003e syscall=202 compat=0 ip=0x446749 code=0xffff0000 device lo entered promiscuous mode TCP: request_sock_TCPv6: Possible SYN flooding on port 20021. Sending cookies. Check SNMP counters. audit: type=1326 audit(1503700726.669:4): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=4028 comm="syz-executor2" exe="/syz-executor2" sig=31 arch=c000003e syscall=202 compat=0 ip=0x446749 code=0xffff0000 audit: type=1326 audit(1503700726.678:5): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=4037 comm="syz-executor1" exe="/syz-executor1" sig=31 arch=c000003e syscall=202 compat=0 ip=0x446749 code=0xffff0000 sock: sock_set_timeout: `syz-executor4' (pid 4081) tries to set negative timeout sock: sock_set_timeout: `syz-executor4' (pid 4100) tries to set negative timeout device syz2 entered promiscuous mode IPv6: Can't replace route, no match found IPv6: Can't replace route, no match found rpcbind: RPC call returned error 22 rpcbind: RPC call returned error 22 sctp: [Deprecated]: syz-executor3 (pid 4364) Use of int in maxseg socket option. Use struct sctp_assoc_value instead sctp: [Deprecated]: syz-executor3 (pid 4401) Use of int in maxseg socket option. Use struct sctp_assoc_value instead kvm [4382]: vcpu0, guest rIP: 0x9110 Hyper-V uhandled wrmsr: 0x4000008f data 0x47 kvm [4382]: vcpu0, guest rIP: 0x9110 Hyper-V uhandled wrmsr: 0x4000008e data 0x47 kvm [4382]: vcpu0, guest rIP: 0x9110 Hyper-V uhandled wrmsr: 0x4000008d data 0x47 kvm [4382]: vcpu0, guest rIP: 0x9110 Hyper-V uhandled wrmsr: 0x4000008c data 0x47 kvm [4382]: vcpu0, guest rIP: 0x9110 Hyper-V uhandled wrmsr: 0x4000008b data 0x47 kvm [4382]: vcpu0, guest rIP: 0x9110 Hyper-V uhandled wrmsr: 0x4000008a data 0x47 kvm [4382]: vcpu0, guest rIP: 0x9110 Hyper-V uhandled wrmsr: 0x40000089 data 0x47 kvm [4382]: vcpu0, guest rIP: 0x9110 Hyper-V uhandled wrmsr: 0x40000088 data 0x47 kvm [4382]: vcpu0, guest rIP: 0x9110 Hyper-V uhandled wrmsr: 0x40000087 data 0x47 kvm [4382]: vcpu0, guest rIP: 0x9110 Hyper-V uhandled wrmsr: 0x40000086 data 0x47 dccp_v4_rcv: dropped packet with invalid checksum do_dccp_setsockopt: sockopt(PACKET_SIZE) is deprecated: fix your app dccp_v4_rcv: dropped packet with invalid checksum do_dccp_setsockopt: sockopt(PACKET_SIZE) is deprecated: fix your app TCP: request_sock_TCP: Possible SYN flooding on port 20012. Sending cookies. Check SNMP counters. audit: type=1326 audit(1503700727.667:6): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=4528 comm="syz-executor1" exe="/syz-executor1" sig=31 arch=c000003e syscall=202 compat=0 ip=0x446749 code=0xffff0000 audit: type=1326 audit(1503700727.745:7): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=4528 comm="syz-executor1" exe="/syz-executor1" sig=31 arch=c000003e syscall=202 compat=0 ip=0x446749 code=0xffff0000 mmap: syz-executor4 (4610) uses deprecated remap_file_pages() syscall. See Documentation/vm/remap_file_pages.txt. Assertion failed! net/irda/ircomm/ircomm_core.c:ircomm_flow_request:475 self != NULL do_dccp_getsockopt: sockopt(PACKET_SIZE) is deprecated: fix your app do_dccp_getsockopt: sockopt(PACKET_SIZE) is deprecated: fix your app audit: type=1326 audit(1503700728.502:8): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=4793 comm="syz-executor2" exe="/syz-executor2" sig=9 arch=c000003e syscall=202 compat=0 ip=0x446749 code=0x0 QAT: Invalid ioctl QAT: Invalid ioctl audit: type=1326 audit(1503700728.639:9): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=4793 comm="syz-executor2" exe="/syz-executor2" sig=9 arch=c000003e syscall=202 compat=0 ip=0x446749 code=0x0 TCP: request_sock_TCPv6: Possible SYN flooding on port 20017. Sending cookies. Check SNMP counters. pit: kvm: requested 2514 ns i8254 timer period limited to 500000 ns 9pnet_virtio: no channels available for device ./control pit: kvm: requested 2514 ns i8254 timer period limited to 500000 ns pit: kvm: requested 2514 ns i8254 timer period limited to 500000 ns pit: kvm: requested 2514 ns i8254 timer period limited to 500000 ns pit: kvm: requested 2514 ns i8254 timer period limited to 500000 ns audit: type=1326 audit(1503700729.756:10): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=5130 comm="syz-executor5" exe="/syz-executor5" sig=31 arch=c000003e syscall=202 compat=0 ip=0x446749 code=0xffff0000 TCP: request_sock_TCP: Possible SYN flooding on port 20016. Sending cookies. Check SNMP counters. dccp_invalid_packet: P.Data Offset(4) too small TCP: request_sock_TCPv6: Possible SYN flooding on port 20009. Sending cookies. Check SNMP counters. nla_parse: 29 callbacks suppressed netlink: 1 bytes leftover after parsing attributes in process `syz-executor3'. netlink: 1 bytes leftover after parsing attributes in process `syz-executor3'. netlink: 1 bytes leftover after parsing attributes in process `syz-executor7'. SELinux: unknown mount option SELinux: unknown mount option TCP: request_sock_TCP: Possible SYN flooding on port 20008. Sending cookies. Check SNMP counters. QAT: Invalid ioctl kvm: pic: non byte write kvm: pic: single mode not supported QAT: Invalid ioctl kvm: pic: non byte write kvm: pic: single mode not supported netlink: 1 bytes leftover after parsing attributes in process `syz-executor0'. netlink: 13 bytes leftover after parsing attributes in process `syz-executor3'. netlink: 1 bytes leftover after parsing attributes in process `syz-executor0'. netlink: 13 bytes leftover after parsing attributes in process `syz-executor3'. SELinux: unrecognized netlink message: protocol=6 nlmsg_type=3131 sclass=netlink_xfrm_socket pig=5601 comm=syz-executor2 SELinux: unrecognized netlink message: protocol=6 nlmsg_type=3131 sclass=netlink_xfrm_socket pig=5601 comm=syz-executor2 netlink: 11 bytes leftover after parsing attributes in process `syz-executor2'. netlink: 11 bytes leftover after parsing attributes in process `syz-executor2'. QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl QAT: Invalid ioctl tmpfs: No value for mount option 'Em2?[f)ԇ$-tc%osXYQ-E FˬgKT\ê65Eq`UVͼLvT(b7OtBDbNZ' tmpfs: No value for mount option 'Em2?[f)ԇ$-tc%osXYQ-E FˬgKT\ê65Eq`UVͼLvT(b7OtBDbNZ' netlink: 8 bytes leftover after parsing attributes in process `syz-executor5'. audit: type=1326 audit(1503700732.727:11): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=5848 comm="syz-executor3" exe="/syz-executor3" sig=31 arch=c000003e syscall=202 compat=0 ip=0x446749 code=0x0 audit: type=1326 audit(1503700732.809:12): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=5848 comm="syz-executor3" exe="/syz-executor3" sig=31 arch=c000003e syscall=202 compat=0 ip=0x446749 code=0x0 audit: type=1326 audit(1503700732.932:13): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=5900 comm="syz-executor7" exe="/syz-executor7" sig=31 arch=c000003e syscall=202 compat=0 ip=0x446749 code=0xffff0000 audit: type=1326 audit(1503700733.045:14): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=5900 comm="syz-executor7" exe="/syz-executor7" sig=31 arch=c000003e syscall=202 compat=0 ip=0x446749 code=0xffff0000 sg_write: data in/out 131038/40 bytes for SCSI command 0x8a-- guessing data in; program syz-executor1 not setting count and/or reply_len properly sg_write: data in/out 131038/40 bytes for SCSI command 0x8a-- guessing data in; program syz-executor1 not setting count and/or reply_len properly sr 1:0:0:0: [sg1] tag#0 FAILED Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK sr 1:0:0:0: [sg1] tag#0 CDB: Read density support 44 00 00 00 00 00 00 00 00 sr 1:0:0:0: [sg1] tag#0 FAILED Result: hostbyte=DID_ERROR driverbyte=DRIVER_OK sr 1:0:0:0: [sg1] tag#0 CDB: Read density support 44 00 00 00 00 00 00 00 00 audit: type=1326 audit(1503700733.568:15): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=6060 comm="syz-executor3" exe="/syz-executor3" sig=0 arch=c000003e syscall=202 compat=0 ip=0x446749 code=0x50000 audit: type=1326 audit(1503700733.568:16): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=6060 comm="syz-executor3" exe="/syz-executor3" sig=0 arch=c000003e syscall=202 compat=0 ip=0x446749 code=0x50000 audit: type=1326 audit(1503700733.571:17): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=6060 comm="syz-executor3" exe="/syz-executor3" sig=0 arch=c000003e syscall=202 compat=0 ip=0x446749 code=0x50000 audit: type=1326 audit(1503700733.571:18): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=6060 comm="syz-executor3" exe="/syz-executor3" sig=0 arch=c000003e syscall=202 compat=0 ip=0x446749 code=0x50000 audit: type=1326 audit(1503700733.573:19): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=6060 comm="syz-executor3" exe="/syz-executor3" sig=0 arch=c000003e syscall=202 compat=0 ip=0x446749 code=0x50000 audit: type=1326 audit(1503700733.573:20): auid=4294967295 uid=0 gid=0 ses=4294967295 subj=kernel pid=6060 comm="syz-executor3" exe="/syz-executor3" sig=0 arch=c000003e syscall=202 compat=0 ip=0x446749 code=0x50000 sctp: [Deprecated]: syz-executor6 (pid 6104) Use of int in max_burst socket option. Use struct sctp_assoc_value instead sctp: [Deprecated]: syz-executor6 (pid 6117) Use of int in max_burst socket option. Use struct sctp_assoc_value instead