Re: tty: deadlock between tty_buffer_flush/n_tracesink_open

From: Dmitry Vyukov
Date: Sun Feb 14 2016 - 13:27:54 EST

Next message: Florian Fainelli: "Re: [PATCH] Revert "net: phy: turn carrier off on phy attach""
Previous message: Clemens Gruber: "Re: [PATCH] Revert "net: phy: turn carrier off on phy attach""
In reply to: Dmitry Vyukov: "tty: deadlock between tty_buffer_flush/n_tracesink_open"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On Sun, Feb 14, 2016 at 7:20 PM, Dmitry Vyukov <dvyukov@xxxxxxxxxx> wrote:
> Hello,
>
> I've finally got the tty deadlock report with lockdep stack collection
> bug fixed. This is on commit 388f7b1d6e8ca06762e2454d28d6c3c55ad0fe95
> (4.5-rc3).

The following report is probably the same issue detected at different
stack. But please double-check that it is indeed the same issue.

[ INFO: possible circular locking dependency detected ]
4.5.0-rc3+ #326 Not tainted
-------------------------------------------------------
kworker/u9:1/26 is trying to acquire lock:
(&buf->lock){+.+...}, at: [<ffffffff82f9f1bf>]
tty_buffer_flush+0xbf/0x3c0 drivers/tty/tty_buffer.c:244

but task is already holding lock:
(&o_tty->termios_rwsem/1){++++..}, at: [<ffffffff82f8d1bb>]
isig+0x9b/0x2c0 drivers/tty/n_tty.c:1137

which lock already depends on the new lock.

the existing dependency chain (in reverse order) is:

-> #4 (&o_tty->termios_rwsem/1){++++..}:
[<ffffffff8145d1bc>] lock_acquire+0x1dc/0x430
kernel/locking/lockdep.c:3589
[<ffffffff8665cbf6>] down_write+0x46/0xa0 kernel/locking/rwsem.c:49
[<ffffffff82f90560>] n_tty_flush_buffer+0x20/0x100
drivers/tty/n_tty.c:374
[<ffffffff82f9f349>] tty_buffer_flush+0x249/0x3c0
drivers/tty/tty_buffer.c:255
[<ffffffff82fa345c>] pty_flush_buffer+0x5c/0x180 drivers/tty/pty.c:225
[<ffffffff82f97b35>] tty_driver_flush_buffer+0x65/0x80
drivers/tty/tty_ioctl.c:94
[<ffffffff848582e1>] hci_uart_tty_open+0x2b1/0x370
drivers/bluetooth/hci_ldisc.c:466
[<ffffffff82f9c028>] tty_ldisc_open.isra.2+0x78/0xd0
drivers/tty/tty_ldisc.c:454
[<ffffffff82f9c612>] tty_set_ldisc+0x292/0x8a0
drivers/tty/tty_ldisc.c:561
[< inline >] tiocsetd drivers/tty/tty_io.c:2655
[<ffffffff82f852ee>] tty_ioctl+0xb2e/0x2160 drivers/tty/tty_io.c:2910
[< inline >] vfs_ioctl fs/ioctl.c:43
[<ffffffff817fc26c>] do_vfs_ioctl+0x18c/0xfb0 fs/ioctl.c:674
[< inline >] SYSC_ioctl fs/ioctl.c:689
[<ffffffff817fd11f>] SyS_ioctl+0x8f/0xc0 fs/ioctl.c:680
[<ffffffff866613f6>] entry_SYSCALL_64_fastpath+0x16/0x7a
arch/x86/entry/entry_64.S:185

-> #3 (&port->buf.lock/1){+.+...}:
[<ffffffff8145d1bc>] lock_acquire+0x1dc/0x430
kernel/locking/lockdep.c:3589
[< inline >] __mutex_lock_common kernel/locking/mutex.c:518
[<ffffffff86657751>] mutex_lock_nested+0xb1/0xa50
kernel/locking/mutex.c:618
[<ffffffff82f9f1bf>] tty_buffer_flush+0xbf/0x3c0
drivers/tty/tty_buffer.c:244
[<ffffffff82fa345c>] pty_flush_buffer+0x5c/0x180 drivers/tty/pty.c:225
[<ffffffff82f97b35>] tty_driver_flush_buffer+0x65/0x80
drivers/tty/tty_ioctl.c:94
[<ffffffff82fb7775>] n_tracesink_open+0x95/0xf0
drivers/tty/n_tracesink.c:85
[<ffffffff82f9c028>] tty_ldisc_open.isra.2+0x78/0xd0
drivers/tty/tty_ldisc.c:454
[<ffffffff82f9c612>] tty_set_ldisc+0x292/0x8a0
drivers/tty/tty_ldisc.c:561
[< inline >] tiocsetd drivers/tty/tty_io.c:2655
[<ffffffff82f852ee>] tty_ioctl+0xb2e/0x2160 drivers/tty/tty_io.c:2910
[< inline >] vfs_ioctl fs/ioctl.c:43
[<ffffffff817fc26c>] do_vfs_ioctl+0x18c/0xfb0 fs/ioctl.c:674
[< inline >] SYSC_ioctl fs/ioctl.c:689
[<ffffffff817fd11f>] SyS_ioctl+0x8f/0xc0 fs/ioctl.c:680
[<ffffffff866613f6>] entry_SYSCALL_64_fastpath+0x16/0x7a
arch/x86/entry/entry_64.S:185

-> #2 (writelock){+.+...}:
[<ffffffff8145d1bc>] lock_acquire+0x1dc/0x430
kernel/locking/lockdep.c:3589
[< inline >] __mutex_lock_common kernel/locking/mutex.c:518
[<ffffffff86657751>] mutex_lock_nested+0xb1/0xa50
kernel/locking/mutex.c:618
[<ffffffff82fb75c4>] n_tracesink_datadrain+0x24/0xc0
drivers/tty/n_tracesink.c:173
[<ffffffff82fb716b>] n_tracerouter_receivebuf+0x2b/0x40
drivers/tty/n_tracerouter.c:176
[< inline >] receive_buf drivers/tty/tty_buffer.c:454
[<ffffffff82f9eb34>] flush_to_ldisc+0x584/0x7f0
drivers/tty/tty_buffer.c:517
[<ffffffff813a3eb6>] process_one_work+0x796/0x1440
kernel/workqueue.c:2037
[<ffffffff813a4c3b>] worker_thread+0xdb/0xfc0 kernel/workqueue.c:2171
[<ffffffff813b7edf>] kthread+0x23f/0x2d0 drivers/block/aoe/aoecmd.c:1303
[<ffffffff866617af>] ret_from_fork+0x3f/0x70
arch/x86/entry/entry_64.S:468

-> #1 (routelock){+.+...}:
[<ffffffff8145d1bc>] lock_acquire+0x1dc/0x430
kernel/locking/lockdep.c:3589
[< inline >] __mutex_lock_common kernel/locking/mutex.c:518
[<ffffffff86657751>] mutex_lock_nested+0xb1/0xa50
kernel/locking/mutex.c:618
[<ffffffff82fb7160>] n_tracerouter_receivebuf+0x20/0x40
drivers/tty/n_tracerouter.c:175
[< inline >] receive_buf drivers/tty/tty_buffer.c:454
[<ffffffff82f9eb34>] flush_to_ldisc+0x584/0x7f0
drivers/tty/tty_buffer.c:517
[<ffffffff813a3eb6>] process_one_work+0x796/0x1440
kernel/workqueue.c:2037
[<ffffffff813a4c3b>] worker_thread+0xdb/0xfc0 kernel/workqueue.c:2171
[<ffffffff813b7edf>] kthread+0x23f/0x2d0 drivers/block/aoe/aoecmd.c:1303
[<ffffffff866617af>] ret_from_fork+0x3f/0x70
arch/x86/entry/entry_64.S:468

-> #0 (&buf->lock){+.+...}:
[< inline >] check_prev_add kernel/locking/lockdep.c:1853
[< inline >] check_prevs_add kernel/locking/lockdep.c:1963
[< inline >] validate_chain kernel/locking/lockdep.c:2148
[<ffffffff81459859>] __lock_acquire+0x31e9/0x4700
kernel/locking/lockdep.c:3210
[<ffffffff8145d1bc>] lock_acquire+0x1dc/0x430
kernel/locking/lockdep.c:3589
[< inline >] __mutex_lock_common kernel/locking/mutex.c:518
[<ffffffff86657751>] mutex_lock_nested+0xb1/0xa50
kernel/locking/mutex.c:618
[<ffffffff82f9f1bf>] tty_buffer_flush+0xbf/0x3c0
drivers/tty/tty_buffer.c:244
[<ffffffff82fa345c>] pty_flush_buffer+0x5c/0x180 drivers/tty/pty.c:225
[<ffffffff82f97b35>] tty_driver_flush_buffer+0x65/0x80
drivers/tty/tty_ioctl.c:94
[<ffffffff82f8d292>] isig+0x172/0x2c0 drivers/tty/n_tty.c:1148
[<ffffffff82f8ff82>] n_tty_receive_signal_char+0x22/0xf0
drivers/tty/n_tty.c:1249
[<ffffffff82f93b9d>] n_tty_receive_char_special+0x128d/0x2b30
drivers/tty/n_tty.c:1298
[< inline >] n_tty_receive_buf_fast drivers/tty/n_tty.c:1618
[< inline >] __receive_buf drivers/tty/n_tty.c:1652
[<ffffffff82f96de3>] n_tty_receive_buf_common+0x19a3/0x2400
drivers/tty/n_tty.c:1750
[<ffffffff82f97873>] n_tty_receive_buf2+0x33/0x40
drivers/tty/n_tty.c:1785
[< inline >] receive_buf drivers/tty/tty_buffer.c:450
[<ffffffff82f9e96f>] flush_to_ldisc+0x3bf/0x7f0
drivers/tty/tty_buffer.c:517
[<ffffffff813a3eb6>] process_one_work+0x796/0x1440
kernel/workqueue.c:2037
[<ffffffff813a4c3b>] worker_thread+0xdb/0xfc0 kernel/workqueue.c:2171
[<ffffffff813b7edf>] kthread+0x23f/0x2d0 drivers/block/aoe/aoecmd.c:1303
[<ffffffff866617af>] ret_from_fork+0x3f/0x70
arch/x86/entry/entry_64.S:468

other info that might help us debug this:

Chain exists of:
&buf->lock --> &port->buf.lock/1 --> &o_tty->termios_rwsem/1
Possible unsafe locking scenario:

CPU0 CPU1
---- ----
lock(&o_tty->termios_rwsem/1);
lock(&port->buf.lock/1);
lock(&o_tty->termios_rwsem/1);
lock(&buf->lock);

*** DEADLOCK ***

6 locks held by kworker/u9:1/26:
#0: ("events_unbound"){.+.+.+}, at: [< inline >]
__write_once_size include/linux/compiler.h:247
#0: ("events_unbound"){.+.+.+}, at: [< inline >]
atomic64_set ./arch/x86/include/asm/atomic64_64.h:33
#0: ("events_unbound"){.+.+.+}, at: [< inline >]
atomic_long_set include/asm-generic/atomic-long.h:56
#0: ("events_unbound"){.+.+.+}, at: [< inline >]
set_work_data kernel/workqueue.c:617
#0: ("events_unbound"){.+.+.+}, at: [< inline >]
set_work_pool_and_clear_pending kernel/workqueue.c:644
#0: ("events_unbound"){.+.+.+}, at: [<ffffffff813a3dba>]
process_one_work+0x69a/0x1440 kernel/workqueue.c:2030
#1: ((&buf->work)){+.+...}, at: [<ffffffff813a3dea>]
process_one_work+0x6ca/0x1440 kernel/workqueue.c:2034
#2: (&tty->ldisc_sem){++++++}, at: [<ffffffff82f9ba4b>]
tty_ldisc_ref+0x1b/0x80 drivers/tty/tty_ldisc.c:283
#3: (&port->buf.lock/1){+.+...}, at: [<ffffffff82f9e691>]
flush_to_ldisc+0xe1/0x7f0 drivers/tty/tty_buffer.c:487
#4: (&o_tty->termios_rwsem/1){++++..}, at: [<ffffffff82f8d1bb>]
isig+0x9b/0x2c0 drivers/tty/n_tty.c:1137
#5: (&tty->ldisc_sem){++++++}, at: [<ffffffff82f9ba4b>]
tty_ldisc_ref+0x1b/0x80 drivers/tty/tty_ldisc.c:283

stack backtrace:
CPU: 1 PID: 26 Comm: kworker/u9:1 Not tainted 4.5.0-rc3+ #326
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
Workqueue: events_unbound flush_to_ldisc
ffffffff87b05080 ffff88003dd274e0 ffffffff82be461f ffffffff00000000
fffffbfff0f60a10 ffffffff895ac8d0 ffffffff895a92d0 ffffffff895ac720
ffff88003dd167b8 ffff88003dd15f00 ffff88003dd27530 ffffffff81452a88
Call Trace:
[< inline >] __dump_stack lib/dump_stack.c:15
[<ffffffff82be461f>] dump_stack+0x12e/0x18f lib/dump_stack.c:51
[<ffffffff81452a88>] print_circular_bug+0x288/0x340
kernel/locking/lockdep.c:1226
[< inline >] check_prev_add kernel/locking/lockdep.c:1853
[< inline >] check_prevs_add kernel/locking/lockdep.c:1963
[< inline >] validate_chain kernel/locking/lockdep.c:2148
[<ffffffff81459859>] __lock_acquire+0x31e9/0x4700 kernel/locking/lockdep.c:3210
[<ffffffff8145d1bc>] lock_acquire+0x1dc/0x430 kernel/locking/lockdep.c:3589
[< inline >] __mutex_lock_common kernel/locking/mutex.c:518
[<ffffffff86657751>] mutex_lock_nested+0xb1/0xa50 kernel/locking/mutex.c:618
[<ffffffff82f9f1bf>] tty_buffer_flush+0xbf/0x3c0 drivers/tty/tty_buffer.c:244
[<ffffffff82fa345c>] pty_flush_buffer+0x5c/0x180 drivers/tty/pty.c:225
[<ffffffff82f97b35>] tty_driver_flush_buffer+0x65/0x80
drivers/tty/tty_ioctl.c:94
[<ffffffff82f8d292>] isig+0x172/0x2c0 drivers/tty/n_tty.c:1148
[<ffffffff82f8ff82>] n_tty_receive_signal_char+0x22/0xf0
drivers/tty/n_tty.c:1249
[<ffffffff82f93b9d>] n_tty_receive_char_special+0x128d/0x2b30
drivers/tty/n_tty.c:1298
[< inline >] n_tty_receive_buf_fast drivers/tty/n_tty.c:1618
[< inline >] __receive_buf drivers/tty/n_tty.c:1652
[<ffffffff82f96de3>] n_tty_receive_buf_common+0x19a3/0x2400
drivers/tty/n_tty.c:1750
[<ffffffff82f97873>] n_tty_receive_buf2+0x33/0x40 drivers/tty/n_tty.c:1785
[< inline >] receive_buf drivers/tty/tty_buffer.c:450
[<ffffffff82f9e96f>] flush_to_ldisc+0x3bf/0x7f0 drivers/tty/tty_buffer.c:517
[<ffffffff813a3eb6>] process_one_work+0x796/0x1440 kernel/workqueue.c:2037
[<ffffffff813a4c3b>] worker_thread+0xdb/0xfc0 kernel/workqueue.c:2171
[<ffffffff813b7edf>] kthread+0x23f/0x2d0 drivers/block/aoe/aoecmd.c:1303
[<ffffffff866617af>] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:468

Next message: Florian Fainelli: "Re: [PATCH] Revert "net: phy: turn carrier off on phy attach""
Previous message: Clemens Gruber: "Re: [PATCH] Revert "net: phy: turn carrier off on phy attach""
In reply to: Dmitry Vyukov: "tty: deadlock between tty_buffer_flush/n_tracesink_open"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]