audit: type=1804 audit(1611677476.960:101): pid=17837 uid=0 auid=0 ses=4 op="invalid_pcr" cause="ToMToU" comm="syz-executor.2" name="/root/syzkaller-testdir473162724/syzkaller.6U9rsM/125/bus" dev="sda1" ino=16473 res=1 ================================ WARNING: inconsistent lock state 4.14.217-syzkaller #0 Not tainted -------------------------------- inconsistent {IN-SOFTIRQ-W} -> {SOFTIRQ-ON-W} usage. syz-executor.5/17810 [HC0[0]:SC0[0]:HE1:SE1] takes: out of order segment: rcv_next 18ACC7A6 seq 18AD09B9 - 18AD0A05 (slock-AF_BLUETOOTH-BTPROTO_SCO){+.?.}, at: [] spin_lock include/linux/spinlock.h:317 [inline] (slock-AF_BLUETOOTH-BTPROTO_SCO){+.?.}, at: [] sco_conn_del+0xbf/0x290 net/bluetooth/sco.c:175 {IN-SOFTIRQ-W} state was registered at: lock_acquire+0x170/0x3f0 kernel/locking/lockdep.c:3998 __raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline] _raw_spin_lock+0x2a/0x40 kernel/locking/spinlock.c:152 spin_lock include/linux/spinlock.h:317 [inline] sco_sock_timeout+0x29/0x1c0 net/bluetooth/sco.c:82 call_timer_fn+0x14a/0x650 kernel/time/timer.c:1280 expire_timers+0x232/0x4d0 kernel/time/timer.c:1319 out of order segment: rcv_next 18ACC7A6 seq 18AD0A05 - 18AD0A51 __run_timers kernel/time/timer.c:1637 [inline] run_timer_softirq+0x1d5/0x5a0 kernel/time/timer.c:1650 __do_softirq+0x254/0xa1d kernel/softirq.c:288 invoke_softirq kernel/softirq.c:368 [inline] irq_exit+0x193/0x240 kernel/softirq.c:409 exiting_irq arch/x86/include/asm/apic.h:648 [inline] smp_apic_timer_interrupt+0x141/0x5e0 arch/x86/kernel/apic/apic.c:1102 apic_timer_interrupt+0x93/0xa0 arch/x86/entry/entry_64.S:793 unwind_next_frame+0xb1d/0x17d0 arch/x86/kernel/unwind_orc.c:437 __save_stack_trace+0x90/0x160 arch/x86/kernel/stacktrace.c:44 save_stack mm/kasan/kasan.c:447 [inline] set_track mm/kasan/kasan.c:459 [inline] kasan_kmalloc+0xeb/0x160 mm/kasan/kasan.c:551 out of order segment: rcv_next 18ACC7A6 seq 18AD0A51 - 18AD0A9D slab_post_alloc_hook mm/slab.h:442 [inline] slab_alloc_node mm/slab.c:3333 [inline] kmem_cache_alloc_node+0x133/0x410 mm/slab.c:3640 out of order segment: rcv_next 18ACC7A6 seq 18AD0A9D - 18AD0AE9 __alloc_skb+0x5c/0x510 net/core/skbuff.c:193 out of order segment: rcv_next 18ACC7A6 seq 18AD0AE9 - 18AD0B35 alloc_skb include/linux/skbuff.h:980 [inline] nlmsg_new include/net/netlink.h:511 [inline] rtmsg_ifa+0xe7/0x1c0 net/ipv4/devinet.c:1704 __inet_insert_ifa+0x68a/0x8f0 net/ipv4/devinet.c:519 inet_rtm_newaddr+0xb81/0xe50 net/ipv4/devinet.c:913 rtnetlink_rcv_msg+0x3be/0xb10 net/core/rtnetlink.c:4316 netlink_rcv_skb+0x125/0x390 net/netlink/af_netlink.c:2433 out of order segment: rcv_next 18ACC7A6 seq 18AD0B35 - 18AD0B81 netlink_unicast_kernel net/netlink/af_netlink.c:1287 [inline] netlink_unicast+0x437/0x610 net/netlink/af_netlink.c:1313 out of order segment: rcv_next 18ACC7A6 seq 18AD0B81 - 18AD0BCD netlink_sendmsg+0x62e/0xb80 net/netlink/af_netlink.c:1878 sock_sendmsg_nosec net/socket.c:646 [inline] sock_sendmsg+0xb5/0x100 net/socket.c:656 SYSC_sendto net/socket.c:1763 [inline] SyS_sendto+0x1c7/0x2c0 net/socket.c:1731 do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292 entry_SYSCALL_64_after_hwframe+0x46/0xbb irq event stamp: 7107 out of order segment: rcv_next 18ACC7A6 seq 18AD0BCD - 18AD0C19 hardirqs last enabled at (7107): [] kfree+0x14a/0x250 mm/slab.c:3816 hardirqs last disabled at (7106): [] kfree+0x6f/0x250 mm/slab.c:3809 softirqs last enabled at (6770): [] spin_unlock_bh include/linux/spinlock.h:362 [inline] softirqs last enabled at (6770): [] peernet2id+0x60/0x70 net/core/net_namespace.c:245 softirqs last disabled at (6768): [] spin_lock_bh include/linux/spinlock.h:322 [inline] softirqs last disabled at (6768): [] peernet2id+0x20/0x70 net/core/net_namespace.c:243 other info that might help us debug this: out of order segment: rcv_next 18ACC7A6 seq 18AD0C19 - 18AD0C65 Possible unsafe locking scenario: out of order segment: rcv_next 18ACC7A6 seq 18AD0C65 - 18AD0CB1 CPU0 ---- lock(slock-AF_BLUETOOTH-BTPROTO_SCO); lock(slock-AF_BLUETOOTH-BTPROTO_SCO); *** DEADLOCK *** 4 locks held by syz-executor.5/17810: #0: (rfkill_global_mutex){+.+.}, at: [] rfkill_fop_write+0xbf/0x3c0 net/rfkill/core.c:1225 #1: out of order segment: rcv_next 18ACC7A6 seq 18AD0CB1 - 18AD0CFD (&hdev->req_lock){+.+.}, at: [] hci_dev_do_close+0x109/0xca0 net/bluetooth/hci_core.c:1576 #2: (&hdev->lock){+.+.}, at: [] hci_dev_do_close+0x21c/0xca0 net/bluetooth/hci_core.c:1607 #3: out of order segment: rcv_next 18ACC7A6 seq 18AD0CFD - 18AD0D49 (hci_cb_list_lock){+.+.}, at: [] hci_disconn_cfm include/net/bluetooth/hci_core.h:1223 [inline] (hci_cb_list_lock){+.+.}, at: [] hci_conn_hash_flush+0xda/0x260 net/bluetooth/hci_conn.c:1393 stack backtrace: CPU: 0 PID: 17810 Comm: syz-executor.5 Not tainted 4.14.217-syzkaller #0 Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011 Call Trace: out of order segment: rcv_next 18ACC7A6 seq 18AD0D49 - 18AD0D95 __dump_stack lib/dump_stack.c:17 [inline] dump_stack+0x1b2/0x281 lib/dump_stack.c:58 print_usage_bug.cold+0x42e/0x570 kernel/locking/lockdep.c:2589 out of order segment: rcv_next 18ACC7A6 seq 18AD0D95 - 18AD0DE1 valid_state kernel/locking/lockdep.c:2602 [inline] mark_lock_irq kernel/locking/lockdep.c:2796 [inline] mark_lock+0xb4d/0x1050 kernel/locking/lockdep.c:3194 mark_irqflags kernel/locking/lockdep.c:3090 [inline] __lock_acquire+0xd5c/0x3f20 kernel/locking/lockdep.c:3448 out of order segment: rcv_next 18ACC7A6 seq 18AD0DE1 - 18AD0E2D out of order segment: rcv_next 18ACC7A6 seq 18AD0E2D - 18AD0E79 lock_acquire+0x170/0x3f0 kernel/locking/lockdep.c:3998 out of order segment: rcv_next 18ACC7A6 seq 18AD0E79 - 18AD0EC5 __raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline] _raw_spin_lock+0x2a/0x40 kernel/locking/spinlock.c:152 spin_lock include/linux/spinlock.h:317 [inline] sco_conn_del+0xbf/0x290 net/bluetooth/sco.c:175 out of order segment: rcv_next 18ACC7A6 seq 18AD0EC5 - 18AD0F11 sco_disconn_cfm+0x65/0xa0 net/bluetooth/sco.c:1134 hci_disconn_cfm include/net/bluetooth/hci_core.h:1226 [inline] hci_conn_hash_flush+0x127/0x260 net/bluetooth/hci_conn.c:1393 hci_dev_do_close+0x535/0xca0 net/bluetooth/hci_core.c:1620 out of order segment: rcv_next 18ACC7A6 seq 18AD0F11 - 18AD0F5D out of order segment: rcv_next 18ACC7A6 seq 18AD0F5D - 18AD0FA9 hci_rfkill_set_block+0xaf/0x120 net/bluetooth/hci_core.c:2050 rfkill_set_block+0x1b2/0x4a0 net/rfkill/core.c:337 rfkill_fop_write+0x1b6/0x3c0 net/rfkill/core.c:1233 out of order segment: rcv_next 18ACC7A6 seq 18AD0FA9 - 18AD0FF5 out of order segment: rcv_next 18ACC7A6 seq 18AD0FF5 - 18AD1041 __vfs_write+0xe4/0x630 fs/read_write.c:480 out of order segment: rcv_next 18ACC7A6 seq 18AD1041 - 18AD108D out of order segment: rcv_next 18ACC7A6 seq 18AD108D - 18AD10D9 out of order segment: rcv_next 18ACC7A6 seq 18AD10D9 - 18AD1125 vfs_write+0x17f/0x4d0 fs/read_write.c:544 out of order segment: rcv_next 18ACC7A6 seq 18AD1125 - 18AD1171 SYSC_write fs/read_write.c:590 [inline] SyS_write+0xf2/0x210 fs/read_write.c:582 out of order segment: rcv_next 18ACC7A6 seq 18AD1171 - 18AD11BD do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292 entry_SYSCALL_64_after_hwframe+0x46/0xbb RIP: 0033:0x45e219 RSP: 002b:00007fa233d93c68 EFLAGS: 00000246 ORIG_RAX: 0000000000000001 RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 000000000045e219 out of order segment: rcv_next 18ACC7A6 seq 18AD11BD - 18AD1209 RDX: 0000000000000008 RSI: 0000000020000000 RDI: 0000000000000004 out of order segment: rcv_next 18ACC7A6 seq 18AD1209 - 18AD1255 RBP: 000000000119bfc0 R08: 0000000000000000 R09: 0000000000000000 R10: 0000000000000000 R11: 0000000000000246 R12: 000000000119bf8c R13: 00007ffe83a11a5f R14: 00007fa233d949c0 R15: 000000000119bf8c audit: type=1804 audit(1611677476.960:102): pid=17866 uid=0 auid=0 ses=4 op="invalid_pcr" cause="open_writers" comm="syz-executor.2" name="/root/syzkaller-testdir473162724/syzkaller.6U9rsM/125/bus" dev="sda1" ino=16473 res=1 out of order segment: rcv_next 18ACC7A6 seq 18AD1255 - 18AD12A1 IPv6: ADDRCONF(NETDEV_CHANGE): vcan0: link becomes ready out of order segment: rcv_next 18ACC7A6 seq 18AD12A1 - 18AD12ED audit: type=1804 audit(1611677477.000:103): pid=17834 uid=0 auid=0 ses=4 op="invalid_pcr" cause="open_writers" comm="syz-executor.0" name="/root/syzkaller-testdir642421478/syzkaller.TEtjNA/259/file0" dev="sda1" ino=16459 res=1 out of order segment: rcv_next 18ACC7A6 seq 18AD12ED - 18AD1339 IPv6: ADDRCONF(NETDEV_CHANGE): vcan0: link becomes ready out of order segment: rcv_next 18ACC7A6 seq 18AD1339 - 18AD1385 chnl_net:chnl_net_open(): err: Unable to register and open device, Err:-19 out of order segment: rcv_next 18ACC7A6 seq 18AD1385 - 18AD13D1 caif:caif_disconnect_client(): nothing to disconnect out of order segment: rcv_next 18ACC7A6 seq 18AD13D1 - 18AD141D out of order segment: rcv_next 18ACC7A6 seq 18AD141D - 18AD1469 out of order segment: rcv_next 18ACC7A6 seq 18AD1469 - 18AD14B5 out of order segment: rcv_next 18ACC7A6 seq 18AD14B5 - 18AD1501 out of order segment: rcv_next 18ACC7A6 seq 18AD1501 - 18AD154D out of order segment: rcv_next 18ACC7A6 seq 18AD154D - 18AD1599 out of order segment: rcv_next 18ACC7A6 seq 18AD1599 - 18AD15E5 out of order segment: rcv_next 18ACC7A6 seq 18AD15E5 - 18AD1631 out of order segment: rcv_next 18ACC7A6 seq 18AD1631 - 18AD167D out of order segment: rcv_next 18ACC7A6 seq 18AD167D - 18AD16C9 out of order segment: rcv_next 18ACC7A6 seq 18AD16C9 - 18AD1715 out of order segment: rcv_next 18ACC7A6 seq 18AD1715 - 18AD1761 out of order segment: rcv_next 18ACC7A6 seq 18AD1761 - 18AD17AD out of order segment: rcv_next 18ACC7A6 seq 18AD17AD - 18AD17F9 out of order segment: rcv_next 18ACC7A6 seq 18AD17F9 - 18AD1845 out of order segment: rcv_next 18ACC7A6 seq 18AD1845 - 18AD1891 out of order segment: rcv_next 18ACC7A6 seq 18AD1891 - 18AD18DD out of order segment: rcv_next 18ACC7A6 seq 18AD18DD - 18AD1929 out of order segment: rcv_next 18ACC7A6 seq 18AD1929 - 18AD1975 out of order segment: rcv_next 18ACC7A6 seq 18AD1975 - 18AD19C1 out of order segment: rcv_next 18ACC7A6 seq 18AD19C1 - 18AD1A0D out of order segment: rcv_next 18ACC7A6 seq 18AD1A0D - 18AD1A59 out of order segment: rcv_next 18ACC7A6 seq 18AD1A59 - 18AD1AA5 out of order segment: rcv_next 18ACC7A6 seq 18AD1AA5 - 18AD1AF1 out of order segment: rcv_next 18ACC7A6 seq 18AD1AF1 - 18AD1B3D out of order segment: rcv_next 18ACC7A6 seq 18AD1B3D - 18AD1B71 audit: type=1804 audit(1611677477.000:104): pid=17868 uid=0 auid=0 ses=4 op="invalid_pcr" cause="ToMToU" comm="syz-executor.0" name="/root/syzkaller-testdir642421478/syzkaller.TEtjNA/259/file0" dev="sda1" ino=16459 res=1 chnl_net:chnl_flowctrl_cb(): NET flowctrl func called flow: CLOSE/DEINIT chnl_net:chnl_net_open(): state disconnected A link change request failed with some changes committed already. Interface caif0 may have been left with an inconsistent configuration, please check. ieee80211 phy17: Selected rate control algorithm 'minstrel_ht' rfkill: input handler enabled ieee80211 phy17: hwaddr 02:00:00:00:11:00 registered netlink: 12 bytes leftover after parsing attributes in process `syz-executor.0'. netlink: 12 bytes leftover after parsing attributes in process `syz-executor.0'. ieee80211 phy18: Selected rate control algorithm 'minstrel_ht' ieee80211 phy18: hwaddr 02:00:00:00:12:00 registered ieee80211 phy19: Selected rate control algorithm 'minstrel_ht' ieee80211 phy19: hwaddr 02:00:00:00:13:00 registered binder: 18025:18031 unknown command 1074546959 netlink: 8 bytes leftover after parsing attributes in process `syz-executor.4'. binder: 18025:18031 ioctl c0306201 20000080 returned -22 IPv6: ADDRCONF(NETDEV_CHANGE): vcan0: link becomes ready IPv6: ADDRCONF(NETDEV_CHANGE): vxcan0: link becomes ready IPv6: ADDRCONF(NETDEV_CHANGE): vxcan1: link becomes ready bond1: Releasing backup interface veth3 bond1: the permanent HWaddr of veth3 - 76:62:a8:0e:12:0f - is still in use by bond1 - set the HWaddr of veth3 to a different address to avoid conflicts device veth3 left promiscuous mode bond1: making interface veth5 the new active one device veth5 entered promiscuous mode bond1: Releasing backup interface veth5 device veth5 left promiscuous mode bond1: making interface veth7 the new active one device veth7 entered promiscuous mode bond1: Releasing backup interface veth7 device veth7 left promiscuous mode bond1: making interface veth9 the new active one device veth9 entered promiscuous mode bond1: Releasing backup interface veth9 device veth9 left promiscuous mode ieee80211 phy20: Selected rate control algorithm 'minstrel_ht' ieee80211 phy20: hwaddr 02:00:00:00:14:00 registered ieee80211 phy21: Selected rate control algorithm 'minstrel_ht' ieee80211 phy21: hwaddr 02:00:00:00:15:00 registered netlink: 8 bytes leftover after parsing attributes in process `syz-executor.4'. IPv6: ADDRCONF(NETDEV_CHANGE): vcan0: link becomes ready IPv6: ADDRCONF(NETDEV_CHANGE): vxcan0: link becomes ready IPv6: ADDRCONF(NETDEV_CHANGE): vxcan1: link becomes ready ieee80211 phy22: Selected rate control algorithm 'minstrel_ht' ieee80211 phy22: hwaddr 02:00:00:00:16:00 registered audit: type=1804 audit(1611677480.480:105): pid=18133 uid=0 auid=0 ses=4 op="invalid_pcr" cause="open_writers" comm="syz-executor.0" name="/root/syzkaller-testdir642421478/syzkaller.TEtjNA/266/bus" dev="sda1" ino=16178 res=1 ieee80211 phy23: Selected rate control algorithm 'minstrel_ht' ieee80211 phy23: hwaddr 02:00:00:00:17:00 registered netlink: 40 bytes leftover after parsing attributes in process `syz-executor.2'. netlink: 40 bytes leftover after parsing attributes in process `syz-executor.2'. ieee80211 phy24: Selected rate control algorithm 'minstrel_ht' ieee80211 phy24: hwaddr 02:00:00:00:18:00 registered ieee80211 phy25: Selected rate control algorithm 'minstrel_ht' ieee80211 phy25: hwaddr 02:00:00:00:19:00 registered audit: type=1804 audit(1611677481.530:106): pid=18133 uid=0 auid=0 ses=4 op="invalid_pcr" cause="open_writers" comm="syz-executor.0" name="/root/syzkaller-testdir642421478/syzkaller.TEtjNA/266/bus" dev="sda1" ino=16178 res=1 ieee80211 phy26: Selected rate control algorithm 'minstrel_ht' ieee80211 phy26: hwaddr 02:00:00:00:1a:00 registered audit: type=1804 audit(1611677481.700:107): pid=18225 uid=0 auid=0 ses=4 op="invalid_pcr" cause="open_writers" comm="syz-executor.0" name="/root/syzkaller-testdir642421478/syzkaller.TEtjNA/267/bus" dev="sda1" ino=16178 res=1 ieee80211 phy27: Selected rate control algorithm 'minstrel_ht' ieee80211 phy27: hwaddr 02:00:00:00:1b:00 registered ieee80211 phy28: Selected rate control algorithm 'minstrel_ht' ieee80211 phy28: hwaddr 02:00:00:00:1c:00 registered ieee80211 phy29: Selected rate control algorithm 'minstrel_ht' ieee80211 phy29: hwaddr 02:00:00:00:1d:00 registered ieee80211 phy30: Selected rate control algorithm 'minstrel_ht' ieee80211 phy30: hwaddr 02:00:00:00:1e:00 registered ieee80211 phy31: Selected rate control algorithm 'minstrel_ht' ieee80211 phy31: hwaddr 02:00:00:00:1f:00 registered IPVS: ftp: loaded support on port[0] = 21 ieee80211 phy32: Selected rate control algorithm 'minstrel_ht' ieee80211 phy32: hwaddr 02:00:00:00:20:00 registered ieee80211 phy33: Selected rate control algorithm 'minstrel_ht' ieee80211 phy33: hwaddr 02:00:00:00:21:00 registered IPVS: ftp: loaded support on port[0] = 21 ieee80211 phy34: Selected rate control algorithm 'minstrel_ht' ieee80211 phy34: hwaddr 02:00:00:00:22:00 registered IPv6: ADDRCONF(NETDEV_CHANGE): vcan0: link becomes ready IPv6: ADDRCONF(NETDEV_CHANGE): vxcan0: link becomes ready IPv6: ADDRCONF(NETDEV_CHANGE): vxcan1: link becomes ready ieee80211 phy35: Selected rate control algorithm 'minstrel_ht' IPv6: ADDRCONF(NETDEV_CHANGE): vcan0: link becomes ready ieee80211 phy35: hwaddr 02:00:00:00:23:00 registered IPv6: ADDRCONF(NETDEV_CHANGE): vxcan0: link becomes ready IPv6: ADDRCONF(NETDEV_CHANGE): vxcan1: link becomes ready ieee80211 phy36: Selected rate control algorithm 'minstrel_ht' ieee80211 phy36: hwaddr 02:00:00:00:24:00 registered ieee80211 phy37: Selected rate control algorithm 'minstrel_ht' ieee80211 phy37: hwaddr 02:00:00:00:25:00 registered ieee80211 phy38: Selected rate control algorithm 'minstrel_ht' ieee80211 phy38: hwaddr 02:00:00:00:26:00 registered ieee80211 phy39: Selected rate control algorithm 'minstrel_ht' ieee80211 phy39: hwaddr 02:00:00:00:27:00 registered ieee80211 phy40: Selected rate control algorithm 'minstrel_ht' ieee80211 phy40: hwaddr 02:00:00:00:28:00 registered ieee80211 phy41: Selected rate control algorithm 'minstrel_ht' ieee80211 phy41: hwaddr 02:00:00:00:29:00 registered ieee80211 phy42: Selected rate control algorithm 'minstrel_ht' ieee80211 phy42: hwaddr 02:00:00:00:2a:00 registered ieee80211 phy43: Selected rate control algorithm 'minstrel_ht' ieee80211 phy43: hwaddr 02:00:00:00:2b:00 registered ieee80211 phy44: Selected rate control algorithm 'minstrel_ht' ieee80211 phy44: hwaddr 02:00:00:00:2c:00 registered ieee80211 phy45: Selected rate control algorithm 'minstrel_ht' ieee80211 phy45: hwaddr 02:00:00:00:2d:00 registered ieee80211 phy46: Selected rate control algorithm 'minstrel_ht' ieee80211 phy46: hwaddr 02:00:00:00:2e:00 registered ieee80211 phy47: Selected rate control algorithm 'minstrel_ht' ieee80211 phy47: hwaddr 02:00:00:00:2f:00 registered ieee80211 phy48: Selected rate control algorithm 'minstrel_ht' ieee80211 phy48: hwaddr 02:00:00:00:30:00 registered ieee80211 phy49: Selected rate control algorithm 'minstrel_ht' ieee80211 phy49: hwaddr 02:00:00:00:31:00 registered ieee80211 phy50: Selected rate control algorithm 'minstrel_ht' ieee80211 phy50: hwaddr 02:00:00:00:32:00 registered ieee80211 phy51: Selected rate control algorithm 'minstrel_ht' ieee80211 phy51: hwaddr 02:00:00:00:33:00 registered ieee80211 phy52: Selected rate control algorithm 'minstrel_ht' ieee80211 phy52: hwaddr 02:00:00:00:34:00 registered ieee80211 phy53: Selected rate control algorithm 'minstrel_ht' ieee80211 phy53: hwaddr 02:00:00:00:35:00 registered ieee80211 phy54: Selected rate control algorithm 'minstrel_ht' ieee80211 phy54: hwaddr 02:00:00:00:36:00 registered ieee80211 phy55: Selected rate control algorithm 'minstrel_ht' ieee80211 phy55: hwaddr 02:00:00:00:37:00 registered ieee80211 phy56: Selected rate control algorithm 'minstrel_ht' ieee80211 phy56: hwaddr 02:00:00:00:38:00 registered ieee80211 phy57: Selected rate control algorithm 'minstrel_ht' ieee80211 phy57: hwaddr 02:00:00:00:39:00 registered