audit: type=1800 audit(1613348695.783:30): pid=21470 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.3" name="bus" dev="sda1" ino=16627 res=0 audit: type=1800 audit(1613348695.823:31): pid=21470 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.3" name="bus" dev="sda1" ino=16627 res=0 ttyprintk ttyprintk: tty_port_close_start: tty->count = 1 port count = 2 ====================================================== WARNING: possible circular locking dependency detected 4.14.218-syzkaller #0 Not tainted ------------------------------------------------------ syz-executor.0/21260 is trying to acquire lock: (console_owner){-...}, at: [] console_trylock_spinning syzkaller/managers/linux-4-14/kernel/kernel/printk/printk.c:1658 [inline] (console_owner){-...}, at: [] vprintk_emit+0x32a/0x620 syzkaller/managers/linux-4-14/kernel/kernel/printk/printk.c:1922 but task is already holding lock: (&(&port->lock)->rlock){-.-.}, at: [] tty_port_close_start.part.0+0x28/0x4c0 syzkaller/managers/linux-4-14/kernel/drivers/tty/tty_port.c:573 which lock already depends on the new lock. the existing dependency chain (in reverse order) is: -> #2 (&(&port->lock)->rlock){-.-.}: __raw_spin_lock_irqsave syzkaller/managers/linux-4-14/kernel/./include/linux/spinlock_api_smp.h:110 [inline] _raw_spin_lock_irqsave+0x8c/0xc0 syzkaller/managers/linux-4-14/kernel/kernel/locking/spinlock.c:160 tty_port_tty_get+0x1d/0x80 syzkaller/managers/linux-4-14/kernel/drivers/tty/tty_port.c:288 tty_port_default_wakeup+0x11/0x40 syzkaller/managers/linux-4-14/kernel/drivers/tty/tty_port.c:46 serial8250_tx_chars+0x3fe/0xbf0 syzkaller/managers/linux-4-14/kernel/drivers/tty/serial/8250/8250_port.c:1810 serial8250_handle_irq.part.0+0x28d/0x330 syzkaller/managers/linux-4-14/kernel/drivers/tty/serial/8250/8250_port.c:1897 serial8250_handle_irq syzkaller/managers/linux-4-14/kernel/drivers/tty/serial/8250/8250_port.c:1870 [inline] serial8250_default_handle_irq+0x8a/0x1f0 syzkaller/managers/linux-4-14/kernel/drivers/tty/serial/8250/8250_port.c:1913 serial8250_interrupt+0xf3/0x210 syzkaller/managers/linux-4-14/kernel/drivers/tty/serial/8250/8250_core.c:129 __handle_irq_event_percpu+0xee/0x7f0 syzkaller/managers/linux-4-14/kernel/kernel/irq/handle.c:147 handle_irq_event_percpu syzkaller/managers/linux-4-14/kernel/kernel/irq/handle.c:187 [inline] handle_irq_event+0xf0/0x250 syzkaller/managers/linux-4-14/kernel/kernel/irq/handle.c:204 handle_edge_irq+0x224/0xc40 syzkaller/managers/linux-4-14/kernel/kernel/irq/chip.c:770 generic_handle_irq_desc syzkaller/managers/linux-4-14/kernel/./include/linux/irqdesc.h:159 [inline] handle_irq+0x35/0x50 syzkaller/managers/linux-4-14/kernel/arch/x86/kernel/irq_64.c:87 do_IRQ+0x93/0x1d0 syzkaller/managers/linux-4-14/kernel/arch/x86/kernel/irq.c:230 ret_from_intr+0x0/0x1e native_safe_halt+0xe/0x10 syzkaller/managers/linux-4-14/kernel/./arch/x86/include/asm/irqflags.h:60 arch_safe_halt syzkaller/managers/linux-4-14/kernel/./arch/x86/include/asm/paravirt.h:94 [inline] default_idle+0x47/0x370 syzkaller/managers/linux-4-14/kernel/arch/x86/kernel/process.c:558 cpuidle_idle_call syzkaller/managers/linux-4-14/kernel/kernel/sched/idle.c:156 [inline] do_idle+0x250/0x3c0 syzkaller/managers/linux-4-14/kernel/kernel/sched/idle.c:246 cpu_startup_entry+0x14/0x20 syzkaller/managers/linux-4-14/kernel/kernel/sched/idle.c:351 start_kernel+0x750/0x770 syzkaller/managers/linux-4-14/kernel/init/main.c:708 secondary_startup_64+0xa5/0xb0 syzkaller/managers/linux-4-14/kernel/arch/x86/kernel/head_64.S:240 -> #1 (&port_lock_key){-.-.}: __raw_spin_lock_irqsave syzkaller/managers/linux-4-14/kernel/./include/linux/spinlock_api_smp.h:110 [inline] _raw_spin_lock_irqsave+0x8c/0xc0 syzkaller/managers/linux-4-14/kernel/kernel/locking/spinlock.c:160 serial8250_console_write+0x7a7/0x9d0 syzkaller/managers/linux-4-14/kernel/drivers/tty/serial/8250/8250_port.c:3253 call_console_drivers syzkaller/managers/linux-4-14/kernel/kernel/printk/printk.c:1725 [inline] console_unlock+0x99d/0xf20 syzkaller/managers/linux-4-14/kernel/kernel/printk/printk.c:2400 vprintk_emit+0x224/0x620 syzkaller/managers/linux-4-14/kernel/kernel/printk/printk.c:1923 vprintk_func+0x58/0x160 syzkaller/managers/linux-4-14/kernel/kernel/printk/printk_safe.c:401 printk+0x9e/0xbc syzkaller/managers/linux-4-14/kernel/kernel/printk/printk.c:1996 register_console+0x6f4/0xad0 syzkaller/managers/linux-4-14/kernel/kernel/printk/printk.c:2719 univ8250_console_init+0x2f/0x3a syzkaller/managers/linux-4-14/kernel/drivers/tty/serial/8250/8250_core.c:691 console_init+0x46/0x53 syzkaller/managers/linux-4-14/kernel/kernel/printk/printk.c:2800 start_kernel+0x52e/0x770 syzkaller/managers/linux-4-14/kernel/init/main.c:634 secondary_startup_64+0xa5/0xb0 syzkaller/managers/linux-4-14/kernel/arch/x86/kernel/head_64.S:240 -> #0 (console_owner){-...}: lock_acquire+0x170/0x3f0 syzkaller/managers/linux-4-14/kernel/kernel/locking/lockdep.c:3998 console_trylock_spinning syzkaller/managers/linux-4-14/kernel/kernel/printk/printk.c:1679 [inline] vprintk_emit+0x367/0x620 syzkaller/managers/linux-4-14/kernel/kernel/printk/printk.c:1922 vprintk_func+0x58/0x160 syzkaller/managers/linux-4-14/kernel/kernel/printk/printk_safe.c:401 printk+0x9e/0xbc syzkaller/managers/linux-4-14/kernel/kernel/printk/printk.c:1996 tty_port_close_start.part.0+0x46c/0x4c0 syzkaller/managers/linux-4-14/kernel/drivers/tty/tty_port.c:575 tty_port_close_start syzkaller/managers/linux-4-14/kernel/drivers/tty/tty_port.c:647 [inline] tty_port_close+0x3b/0x130 syzkaller/managers/linux-4-14/kernel/drivers/tty/tty_port.c:640 tty_release+0x40b/0x10d0 syzkaller/managers/linux-4-14/kernel/drivers/tty/tty_io.c:1670 __fput+0x25f/0x7a0 syzkaller/managers/linux-4-14/kernel/fs/file_table.c:210 task_work_run+0x11f/0x190 syzkaller/managers/linux-4-14/kernel/kernel/task_work.c:113 get_signal+0x18a3/0x1ca0 syzkaller/managers/linux-4-14/kernel/kernel/signal.c:2234 do_signal+0x7c/0x1550 syzkaller/managers/linux-4-14/kernel/arch/x86/kernel/signal.c:814 exit_to_usermode_loop+0x160/0x200 syzkaller/managers/linux-4-14/kernel/arch/x86/entry/common.c:160 prepare_exit_to_usermode syzkaller/managers/linux-4-14/kernel/arch/x86/entry/common.c:199 [inline] syscall_return_slowpath syzkaller/managers/linux-4-14/kernel/arch/x86/entry/common.c:270 [inline] do_syscall_64+0x4a3/0x640 syzkaller/managers/linux-4-14/kernel/arch/x86/entry/common.c:297 entry_SYSCALL_64_after_hwframe+0x46/0xbb other info that might help us debug this: Chain exists of: console_owner --> &port_lock_key --> &(&port->lock)->rlock Possible unsafe locking scenario: CPU0 CPU1 ---- ---- lock(&(&port->lock)->rlock); lock(&port_lock_key); lock(&(&port->lock)->rlock); lock(console_owner); *** DEADLOCK *** 2 locks held by syz-executor.0/21260: #0: (&tty->legacy_mutex){+.+.}, at: [] tty_lock+0x5f/0x70 syzkaller/managers/linux-4-14/kernel/drivers/tty/tty_mutex.c:19 #1: (&(&port->lock)->rlock){-.-.}, at: [] tty_port_close_start.part.0+0x28/0x4c0 syzkaller/managers/linux-4-14/kernel/drivers/tty/tty_port.c:573 stack backtrace: CPU: 1 PID: 21260 Comm: syz-executor.0 Not tainted 4.14.218-syzkaller #0 Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011 Call Trace: __dump_stack syzkaller/managers/linux-4-14/kernel/lib/dump_stack.c:17 [inline] dump_stack+0x1b2/0x281 syzkaller/managers/linux-4-14/kernel/lib/dump_stack.c:58 print_circular_bug.constprop.0.cold+0x2d7/0x41e syzkaller/managers/linux-4-14/kernel/kernel/locking/lockdep.c:1258 check_prev_add syzkaller/managers/linux-4-14/kernel/kernel/locking/lockdep.c:1905 [inline] check_prevs_add syzkaller/managers/linux-4-14/kernel/kernel/locking/lockdep.c:2022 [inline] validate_chain syzkaller/managers/linux-4-14/kernel/kernel/locking/lockdep.c:2464 [inline] __lock_acquire+0x2e0e/0x3f20 syzkaller/managers/linux-4-14/kernel/kernel/locking/lockdep.c:3491 lock_acquire+0x170/0x3f0 syzkaller/managers/linux-4-14/kernel/kernel/locking/lockdep.c:3998 console_trylock_spinning syzkaller/managers/linux-4-14/kernel/kernel/printk/printk.c:1679 [inline] vprintk_emit+0x367/0x620 syzkaller/managers/linux-4-14/kernel/kernel/printk/printk.c:1922 vprintk_func+0x58/0x160 syzkaller/managers/linux-4-14/kernel/kernel/printk/printk_safe.c:401 printk+0x9e/0xbc syzkaller/managers/linux-4-14/kernel/kernel/printk/printk.c:1996 tty_port_close_start.part.0+0x46c/0x4c0 syzkaller/managers/linux-4-14/kernel/drivers/tty/tty_port.c:575 tty_port_close_start syzkaller/managers/linux-4-14/kernel/drivers/tty/tty_port.c:647 [inline] tty_port_close+0x3b/0x130 syzkaller/managers/linux-4-14/kernel/drivers/tty/tty_port.c:640 tty_release+0x40b/0x10d0 syzkaller/managers/linux-4-14/kernel/drivers/tty/tty_io.c:1670 __fput+0x25f/0x7a0 syzkaller/managers/linux-4-14/kernel/fs/file_table.c:210 task_work_run+0x11f/0x190 syzkaller/managers/linux-4-14/kernel/kernel/task_work.c:113 get_signal+0x18a3/0x1ca0 syzkaller/managers/linux-4-14/kernel/kernel/signal.c:2234 do_signal+0x7c/0x1550 syzkaller/managers/linux-4-14/kernel/arch/x86/kernel/signal.c:814 exit_to_usermode_loop+0x160/0x200 syzkaller/managers/linux-4-14/kernel/arch/x86/entry/common.c:160 prepare_exit_to_usermode syzkaller/managers/linux-4-14/kernel/arch/x86/entry/common.c:199 [inline] syscall_return_slowpath syzkaller/managers/linux-4-14/kernel/arch/x86/entry/common.c:270 [inline] do_syscall_64+0x4a3/0x640 syzkaller/managers/linux-4-14/kernel/arch/x86/entry/common.c:297 entry_SYSCALL_64_after_hwframe+0x46/0xbb RIP: 0033:0x465d99 RSP: 002b:00007efd1c11b188 EFLAGS: 00000246 ORIG_RAX: 0000000000000010 RAX: 0000000000000000 RBX: 000000000056bf60 RCX: 0000000000465d99 RDX: 0000000020000000 RSI: 0000000000005423 RDI: 0000000000000003 RBP: 00000000004bcf27 R08: 0000000000000000 R09: 0000000000000000 R10: 0000000000000000 R11: 0000000000000246 R12: 000000000056bf60 R13: 00007fff566b5bef R14: 00007efd1c11b300 R15: 0000000000022000 audit: type=1326 audit(1613348696.703:32): auid=4294967295 uid=0 gid=0 ses=4294967295 pid=21589 comm="syz-executor.1" exe="/root/syz-executor.1" sig=9 arch=c000003e syscall=231 compat=0 ip=0x465d99 code=0x0 squashfs: SQUASHFS error: unable to read xattr id index table EXT4-fs (loop4): ext4_check_descriptors: Inode bitmap for group 0 not in group (block 0)! EXT4-fs (loop5): ext4_check_descriptors: Checksum for group 0 failed (60935!=0) EXT4-fs (loop4): group descriptors corrupted! IPv6: ADDRCONF(NETDEV_CHANGE): vcan0: link becomes ready EXT4-fs (loop5): orphan cleanup on readonly fs audit: type=1326 audit(1613348696.863:33): auid=4294967295 uid=0 gid=0 ses=4294967295 pid=21589 comm="syz-executor.1" exe="/root/syz-executor.1" sig=9 arch=c000003e syscall=231 compat=0 ip=0x465d99 code=0x0 IPv6: ADDRCONF(NETDEV_CHANGE): vxcan0: link becomes ready EXT4-fs (loop4): Unrecognized mount option "[" or missing value EXT4-fs error (device loop5): ext4_orphan_get:1266: comm syz-executor.5: bad orphan inode 33554432 EXT4-fs (loop5): mounted filesystem without journal. Opts: ,errors=continue FAT-fs (loop0): Unrecognized mount option "func=KEXEC_INITRAMFS_CHECK" or missing value overlayfs: unrecognized mount option "Lowerdir=./dile0" or missing value IPv6: ADDRCONF(NETDEV_CHANGE): vxcan1: link becomes ready IPVS: ftp: loaded support on port[0] = 21 squashfs: SQUASHFS error: unable to read xattr id index table FAT-fs (loop0): Unrecognized mount option "func=KEXEC_INITRAMFS_CHECK" or missing value device bond1 entered promiscuous mode IPv6: ADDRCONF(NETDEV_UP): bond1: link is not ready 8021q: adding VLAN 0 to HW filter on device bond1 bridge0: port 3(team0) entered blocking state bridge0: port 3(team0) entered disabled state device team0 entered promiscuous mode device team_slave_0 entered promiscuous mode device team_slave_1 entered promiscuous mode bridge0: port 3(team0) entered blocking state bridge0: port 3(team0) entered forwarding state device team0 left promiscuous mode device team_slave_0 left promiscuous mode device team_slave_1 left promiscuous mode bridge0: port 3(team0) entered disabled state bridge0: port 3(team0) entered blocking state bridge0: port 3(team0) entered disabled state device team0 entered promiscuous mode device team_slave_0 entered promiscuous mode device team_slave_1 entered promiscuous mode bridge0: port 3(team0) entered blocking state bridge0: port 3(team0) entered forwarding state device batadv0 entered promiscuous mode 8021q: adding VLAN 0 to HW filter on device batadv0 8021q: adding VLAN 0 to HW filter on device batadv0 overlayfs: unrecognized mount option "lowerdir.:file0" or missing value tmpfs: Bad value '00000000000000060928' for mount option 'uid' overlayfs: unrecognized mount option "lowerdir.:file0" or missing value tmpfs: Bad value '00000000000000060928' for mount option 'uid' overlayfs: filesystem on './bus' not supported as upperdir netlink: 24 bytes leftover after parsing attributes in process `syz-executor.0'. base_sock_release(ffff8880512431c0) sk=ffff8880b4b78bc0 netlink: 24 bytes leftover after parsing attributes in process `syz-executor.0'. base_sock_release(ffff888041eb5080) sk=ffff888052321200 REISERFS warning (device loop0): sh-2012 read_super_block: found unknown format "55554" of reiserfs with non-standard magic REISERFS warning (device loop0): sh-2021 reiserfs_fill_super: can not find reiserfs on loop0 REISERFS warning (device loop0): sh-2012 read_super_block: found unknown format "55554" of reiserfs with non-standard magic REISERFS warning (device loop0): sh-2021 reiserfs_fill_super: can not find reiserfs on loop0 IPVS: ftp: loaded support on port[0] = 21 kvm [22013]: vcpu0, guest rIP: 0x14c Hyper-V uhandled wrmsr: 0x40000040 data 0xf IPVS: ftp: loaded support on port[0] = 21 MINIX-fs: mounting unchecked file system, running fsck is recommended kvm [22060]: vcpu0, guest rIP: 0x14c Hyper-V uhandled wrmsr: 0x40000040 data 0xf kvm [22110]: vcpu0, guest rIP: 0x14c Hyper-V uhandled wrmsr: 0x40000040 data 0xf kvm [22137]: vcpu0, guest rIP: 0x14c Hyper-V uhandled wrmsr: 0x40000040 data 0xf xt_hashlimit: max too large, truncated to 1048576 ip6_tables: ip6tables: counters copy to user failed while replacing table kvm [22162]: vcpu0, guest rIP: 0x14c Hyper-V uhandled wrmsr: 0x40000040 data 0xf xt_hashlimit: max too large, truncated to 1048576 netlink: 8 bytes leftover after parsing attributes in process `syz-executor.5'. kvm [22189]: vcpu0, guest rIP: 0x14c Hyper-V uhandled wrmsr: 0x40000040 data 0xf netlink: 8 bytes leftover after parsing attributes in process `syz-executor.5'. blktrace: Concurrent blktraces are not allowed on loop0 blktrace: Concurrent blktraces are not allowed on loop0 kvm [22237]: vcpu0, guest rIP: 0x14c Hyper-V uhandled wrmsr: 0x40000040 data 0xf kvm [22239]: vcpu0, guest rIP: 0x14c Hyper-V uhandled wrmsr: 0x40000040 data 0xf blktrace: Concurrent blktraces are not allowed on loop0 device syzkaller1 entered promiscuous mode blktrace: Concurrent blktraces are not allowed on loop0 IPv6: ADDRCONF(NETDEV_CHANGE): vcan0: link becomes ready kvm [22282]: vcpu0, guest rIP: 0x14c Hyper-V uhandled wrmsr: 0x40000040 data 0xf IPv6: ADDRCONF(NETDEV_CHANGE): vxcan0: link becomes ready kvm [22282]: vcpu0, guest rIP: 0x14c Hyper-V uhandled wrmsr: 0x40000057 data 0x81 IPv6: ADDRCONF(NETDEV_CHANGE): vxcan1: link becomes ready IPv6: ADDRCONF(NETDEV_CHANGE): vcan0: link becomes ready IPv6: ADDRCONF(NETDEV_CHANGE): vxcan0: link becomes ready IPv6: ADDRCONF(NETDEV_CHANGE): vxcan1: link becomes ready audit: type=1800 audit(1613348703.604:34): pid=22327 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.1" name="bus" dev="sda1" ino=16695 res=0 IPv6: ADDRCONF(NETDEV_CHANGE): vcan0: link becomes ready IPv6: ADDRCONF(NETDEV_CHANGE): vxcan0: link becomes ready overlayfs: fs on 'file0' does not support file handles, falling back to index=off. IPv6: ADDRCONF(NETDEV_CHANGE): vxcan1: link becomes ready audit: type=1804 audit(1613348703.654:35): pid=22327 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.1" name="/root/syzkaller-testdir281237437/syzkaller.gjUrfP/205/bus" dev="sda1" ino=16695 res=1 audit: type=1804 audit(1613348703.654:36): pid=22327 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.1" name="/root/syzkaller-testdir281237437/syzkaller.gjUrfP/205/bus" dev="sda1" ino=16695 res=1 audit: type=1804 audit(1613348703.784:37): pid=22346 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.1" name="/root/syzkaller-testdir281237437/syzkaller.gjUrfP/206/memory.events" dev="sda1" ino=16699 res=1 audit: type=1800 audit(1613348703.784:38): pid=22346 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.1" name="memory.events" dev="sda1" ino=16699 res=0 audit: type=1804 audit(1613348703.794:39): pid=22346 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="ToMToU" comm="syz-executor.1" name="/root/syzkaller-testdir281237437/syzkaller.gjUrfP/206/memory.events" dev="sda1" ino=16699 res=1 audit: type=1800 audit(1613348703.794:40): pid=22346 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.1" name="memory.events" dev="sda1" ino=16699 res=0 audit: type=1804 audit(1613348703.854:41): pid=22356 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="ToMToU" comm="syz-executor.1" name="/root/syzkaller-testdir281237437/syzkaller.gjUrfP/206/memory.events" dev="sda1" ino=16699 res=1 IPv6: ADDRCONF(NETDEV_CHANGE): vcan0: link becomes ready IPv6: ADDRCONF(NETDEV_CHANGE): vxcan0: link becomes ready IPv6: ADDRCONF(NETDEV_CHANGE): vxcan1: link becomes ready Bluetooth: hci5 command 0x0406 tx timeout Bluetooth: hci3 command 0x0406 tx timeout Bluetooth: hci1 command 0x0406 tx timeout Bluetooth: hci4 command 0x0406 tx timeout