possible deadlock in tty_port_close

possible deadlock in tty_port_close_start
Status: upstream: reported C repro on 2020/02/13 04:57
Reported-by: syzbot+044000e5acdb5e1d5eed@syzkaller.appspotmail.com
First crash: 174d, last: 8d20h

Cause bisection: the cause commit could be any of (bisect log):

  9211bfbff80a netfilter: add missing IS_ENABLED(CONFIG_BRIDGE_NETFILTER) checks to header-file.
  47e640af2e49 netfilter: add missing IS_ENABLED(CONFIG_NF_TABLES) check to header-file.
  a1b2f04ea527 netfilter: add missing includes to a number of header-files.
  0abc8bf4f284 netfilter: add missing IS_ENABLED(CONFIG_NF_CONNTRACK) checks to some header-files.
  bd96b4c75675 netfilter: inline four headers files into another one.
  43dd16efc7f2 netfilter: nf_tables: store data in offload context registers
  78458e3e08cd netfilter: add missing IS_ENABLED(CONFIG_NETFILTER) checks to some header-files.
  20a9379d9a03 netfilter: remove "#ifdef __KERNEL__" guards from some headers.
  bd8699e9e292 netfilter: nft_bitwise: add offload support
  2a475c409fe8 kbuild: remove all netfilter headers from header-test blacklist.
  7e59b3fea2a2 netfilter: remove unnecessary spaces
  1b90af292e71 ipvs: Improve robustness to the ipvs sysctl
  5785cf15fd74 netfilter: nf_tables: add missing prototypes.
  0a30ba509fde netfilter: nf_nat_proto: make tables static
  e84fb4b3666d netfilter: conntrack: use shared sysctl constants
  105333435b4f netfilter: connlabels: prefer static lock initialiser
  8c0bb7873815 netfilter: synproxy: rename mss synproxy_options field
  c162610c7db2 Merge git://git.kernel.org/pub/scm/linux/kernel/git/pablo/nf-next

Fix bisection: failed (bisect log)

similar bugs (2):
Kernel	Title	Repro	Bisected	Count	Last	Reported	Patched	Status
linux-4.19	possible deadlock in tty_port_close_start			11	1d13h	181d	0/1	upstream: reported on 2020/02/05 23:51
linux-4.14	possible deadlock in tty_port_close_start			8	8d01h	172d	0/1	upstream: reported on 2020/02/15 19:33

Sample crash report:

======================================================
WARNING: possible circular locking dependency detected
5.7.0-syzkaller #0 Not tainted
------------------------------------------------------
syz-executor095/20133 is trying to acquire lock:
ffffffff899b2d40 (console_owner){-.-.}-{0:0}, at: console_trylock_spinning kernel/printk/printk.c:1763 [inline]
ffffffff899b2d40 (console_owner){-.-.}-{0:0}, at: vprintk_emit+0x425/0x730 kernel/printk/printk.c:2031

but task is already holding lock:
ffffffff8d1db4b8 (&port->lock#2){-.-.}-{2:2}, at: tty_port_close_start.part.0+0x28/0x550 drivers/tty/tty_port.c:567

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #2 (&port->lock#2){-.-.}-{2:2}:
       __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
       _raw_spin_lock_irqsave+0x8c/0xbf kernel/locking/spinlock.c:159
       tty_port_tty_get+0x1f/0x100 drivers/tty/tty_port.c:288
       tty_port_default_wakeup+0x11/0x40 drivers/tty/tty_port.c:47
       serial8250_tx_chars+0x48f/0xa60 drivers/tty/serial/8250/8250_port.c:1828
       serial8250_handle_irq.part.0+0x328/0x3d0 drivers/tty/serial/8250/8250_port.c:1915
       serial8250_handle_irq drivers/tty/serial/8250/8250_port.c:1888 [inline]
       serial8250_default_handle_irq+0xb5/0x140 drivers/tty/serial/8250/8250_port.c:1931
       serial8250_interrupt+0xe6/0x190 drivers/tty/serial/8250/8250_core.c:126
       __handle_irq_event_percpu+0x22e/0xa50 kernel/irq/handle.c:156
       handle_irq_event_percpu+0x76/0x160 kernel/irq/handle.c:196
       handle_irq_event+0xa2/0x12d kernel/irq/handle.c:213
       handle_edge_irq+0x24b/0x8c0 kernel/irq/chip.c:830
       generic_handle_irq_desc include/linux/irqdesc.h:156 [inline]
       do_IRQ+0xd5/0x270 arch/x86/kernel/irq.c:250
       ret_from_intr+0x0/0x2b
       native_safe_halt+0xe/0x10 arch/x86/include/asm/irqflags.h:60
       arch_safe_halt arch/x86/include/asm/paravirt.h:144 [inline]
       default_idle+0x49/0x350 arch/x86/kernel/process.c:697
       cpuidle_idle_call kernel/sched/idle.c:154 [inline]
       do_idle+0x393/0x690 kernel/sched/idle.c:269
       cpu_startup_entry+0x14/0x20 kernel/sched/idle.c:365
       start_kernel+0x9be/0x9fb init/main.c:1041
       secondary_startup_64+0xa4/0xb0 arch/x86/kernel/head_64.S:242

-> #1 (&port->lock){-.-.}-{2:2}:
       __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
       _raw_spin_lock_irqsave+0x8c/0xbf kernel/locking/spinlock.c:159
       serial8250_console_write+0x20d/0xb00 drivers/tty/serial/8250/8250_port.c:3240
       call_console_drivers kernel/printk/printk.c:1827 [inline]
       console_unlock+0xac7/0xf00 kernel/printk/printk.c:2515
       vprintk_emit+0x2c4/0x730 kernel/printk/printk.c:2032
       vprintk_func+0x8f/0x1a6 kernel/printk/printk_safe.c:386
       printk+0xba/0xed kernel/printk/printk.c:2092
       register_console kernel/printk/printk.c:2868 [inline]
       register_console+0x55f/0x7e0 kernel/printk/printk.c:2747
       univ8250_console_init+0x3a/0x46 drivers/tty/serial/8250/8250_core.c:690
       console_init+0x43f/0x646 kernel/printk/printk.c:2968
       start_kernel+0x76e/0x9fb init/main.c:969
       secondary_startup_64+0xa4/0xb0 arch/x86/kernel/head_64.S:242

-> #0 (console_owner){-.-.}-{0:0}:
       check_prev_add kernel/locking/lockdep.c:2496 [inline]
       check_prevs_add kernel/locking/lockdep.c:2601 [inline]
       validate_chain kernel/locking/lockdep.c:3218 [inline]
       __lock_acquire+0x2a9a/0x48a0 kernel/locking/lockdep.c:4380
       lock_acquire+0x1f2/0x8f0 kernel/locking/lockdep.c:4959
       console_trylock_spinning kernel/printk/printk.c:1784 [inline]
       vprintk_emit+0x462/0x730 kernel/printk/printk.c:2031
       vprintk_func+0x8f/0x1a6 kernel/printk/printk_safe.c:386
       printk+0xba/0xed kernel/printk/printk.c:2092
       tty_port_close_start.part.0+0x4f7/0x550 drivers/tty/tty_port.c:569
       tty_port_close_start drivers/tty/tty_port.c:641 [inline]
       tty_port_close+0x46/0xf0 drivers/tty/tty_port.c:634
       tty_release+0x3b9/0xe90 drivers/tty/tty_io.c:1679
       __fput+0x33e/0x880 fs/file_table.c:281
       task_work_run+0xf4/0x1b0 kernel/task_work.c:123
       exit_task_work include/linux/task_work.h:22 [inline]
       do_exit+0xb3f/0x2de0 kernel/exit.c:806
       do_group_exit+0x125/0x340 kernel/exit.c:904
       __do_sys_exit_group kernel/exit.c:915 [inline]
       __se_sys_exit_group kernel/exit.c:913 [inline]
       __x64_sys_exit_group+0x3a/0x50 kernel/exit.c:913
       do_syscall_64+0xf6/0x7d0 arch/x86/entry/common.c:295
       entry_SYSCALL_64_after_hwframe+0x49/0xb3

other info that might help us debug this:

Chain exists of:
  console_owner --> &port->lock --> &port->lock#2

 Possible unsafe locking scenario:

       CPU0                    CPU1
       ----                    ----
  lock(&port->lock#2);
                               lock(&port->lock);
                               lock(&port->lock#2);
  lock(console_owner);

 *** DEADLOCK ***

2 locks held by syz-executor095/20133:
 #0: ffff888027d651c0 (&tty->legacy_mutex){+.+.}-{3:3}, at: tty_lock+0xbd/0x120 drivers/tty/tty_mutex.c:19
 #1: ffffffff8d1db4b8 (&port->lock#2){-.-.}-{2:2}, at: tty_port_close_start.part.0+0x28/0x550 drivers/tty/tty_port.c:567

stack backtrace:
CPU: 3 PID: 20133 Comm: syz-executor095 Not tainted 5.7.0-syzkaller #0
Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.12.0-59-gc9ba5276e321-prebuilt.qemu.org 04/01/2014
Call Trace:
 __dump_stack lib/dump_stack.c:77 [inline]
 dump_stack+0x188/0x20d lib/dump_stack.c:118
 check_noncircular+0x32e/0x3e0 kernel/locking/lockdep.c:1827
 check_prev_add kernel/locking/lockdep.c:2496 [inline]
 check_prevs_add kernel/locking/lockdep.c:2601 [inline]
 validate_chain kernel/locking/lockdep.c:3218 [inline]
 __lock_acquire+0x2a9a/0x48a0 kernel/locking/lockdep.c:4380
 lock_acquire+0x1f2/0x8f0 kernel/locking/lockdep.c:4959
 console_trylock_spinning kernel/printk/printk.c:1784 [inline]
 vprintk_emit+0x462/0x730 kernel/printk/printk.c:2031
 vprintk_func+0x8f/0x1a6 kernel/printk/printk_safe.c:386
 printk+0xba/0xed kernel/printk/printk.c:2092
 tty_port_close_start.part.0+0x4f7/0x550 drivers/tty/tty_port.c:569
 tty_port_close_start drivers/tty/tty_port.c:641 [inline]
 tty_port_close+0x46/0xf0 drivers/tty/tty_port.c:634
 tty_release+0x3b9/0xe90 drivers/tty/tty_io.c:1679
 __fput+0x33e/0x880 fs/file_table.c:281
 task_work_run+0xf4/0x1b0 kernel/task_work.c:123
 exit_task_work include/linux/task_work.h:22 [inline]
 do_exit+0xb3f/0x2de0 kernel/exit.c:806
 do_group_exit+0x125/0x340 kernel/exit.c:904
 __do_sys_exit_group kernel/exit.c:915 [inline]
 __se_sys_exit_group kernel/exit.c:913 [inline]
 __x64_sys_exit_group+0x3a/0x50 kernel/exit.c:913
 do_syscall_64+0xf6/0x7d0 arch/x86/entry/common.c:295
 entry_SYSCALL_64_after_hwframe+0x49/0xb3
RIP: 0033:0x438738
Code: Bad RIP value.
RSP: 002b:00007ffc5e72aec8 EFLAGS: 00000246 ORIG_RAX: 00000000000000e7
RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 0000000000438738
RDX: 0000000000000000 RSI: 000000000000003c RDI: 0000000000000000
RBP: 00000000004b3cd0 R08: 00000000000000e7 R09: ffffffffffffffd0
R10: 00007ffc5e72af40 R11: 0000000000000246 R12: 0000000000000001
R13: 00000000006c7320 R14: 00007ffc5e72af38 R15: 20c49ba5e353f7cf

Crashes (10):
Manager	Time	Kernel	Commit	Syzkaller	Config	Log	Report	Syz repro	C repro	Maintainers
ci-qemu-upstream	2020/06/13 18:52	upstream	435faf5c	dbce178a	.config	log	report	syz	C	gregkh@linuxfoundation.org, jslaby@suse.com, linux-kernel@vger.kernel.org
ci-upstream-kasan-gce-root	2020/02/17 14:42	upstream	11a48a5a	2b411596	.config	log	report	syz	C	gregkh@linuxfoundation.org, jslaby@suse.com, linux-kernel@vger.kernel.org
ci-upstream-kasan-gce-root	2020/07/28 02:35	upstream	92ed3019	cb93dc6a	.config	log	report			gregkh@linuxfoundation.org, jslaby@suse.com, linux-kernel@vger.kernel.org
ci-upstream-kasan-gce-root	2020/06/18 05:18	upstream	7ae77150	b9f3810b	.config	log	report			gregkh@linuxfoundation.org, jslaby@suse.com, linux-kernel@vger.kernel.org
ci-upstream-kasan-gce-root	2020/06/02 03:38	upstream	9bf9511e	a0331e89	.config	log	report			gregkh@linuxfoundation.org, jslaby@suse.com, linux-kernel@vger.kernel.org
ci-upstream-kasan-gce-selinux-root	2020/05/30 19:59	upstream	86852175	6f3e1c7c	.config	log	report			gregkh@linuxfoundation.org, jslaby@suse.com, linux-kernel@vger.kernel.org
ci-upstream-kasan-gce-root	2020/03/27 14:14	upstream	f3e69428	7d95711b	.config	log	report			gregkh@linuxfoundation.org, jslaby@suse.com, linux-kernel@vger.kernel.org
ci-upstream-kasan-gce-root	2020/02/28 13:35	upstream	f8788d86	59b57593	.config	log	report			gregkh@linuxfoundation.org, jslaby@suse.com, linux-kernel@vger.kernel.org
ci-upstream-kasan-gce-root	2020/02/12 23:17	upstream	f2850dd5	84f4fc8a	.config	log	report			gregkh@linuxfoundation.org, jslaby@suse.com, linux-kernel@vger.kernel.org
ci-upstream-linux-next-kasan-gce-root	2020/02/20 00:52	linux-next	1d7f85df	b690a6e3	.config	log	report			gregkh@linuxfoundation.org, jslaby@suse.com, linux-kernel@vger.kernel.org