Re: tty: deadlock between n_tracerouter_receivebuf and flush_to_ldisc

[Dmitry Vyukov]

On Fri, Jan 15, 2016 at 6:22 PM, Dmitry Vyukov <dvyukov@xxxxxxxxxx> wrote:
> On Fri, Jan 15, 2016 at 5:33 PM, One Thousand Gnomes
> <gnomes@xxxxxxxxxxxxxxxxxxx> wrote:
>> On Fri, 15 Jan 2016 08:51:39 +0100
>> Dmitry Vyukov <dvyukov@xxxxxxxxxx> wrote:
>>
>>> On Wed, Dec 30, 2015 at 11:44 AM, Dmitry Vyukov <dvyukov@xxxxxxxxxx> wrote:
>>> > Hello,
>>> >
>>> > I've got the following lock order inversion report on
>>> > 8513342170278468bac126640a5d2d12ffbff106 (Dec 28). Unfortunately I
>>> > failed to find a reproducer for it.
>>>
>>> Ping. This is the most frequent failure during my testing now. J
>>> Freyensee, you seem to wrote drivers/tty/n_tracerouter.c. Please take
>>> a look. Thanks.
>>
>> This driver hasn't changed since forever, nor does it look like a bug in
>> n_tracerouter.
>>
>> This first two threads of execution is for the old line discipline so
>> don't occur at the same time as executing tracerouter.
>>
>> This is opening the port with the tracerouter discipline as you change
>> line discipline. The core code locks the tty and then takes the ldisc
>> lock. Closes the old ldisc, opens the new, opening the new takes the
>> router lock.
>>
>>         (tty_lock, tty_ldisc_lock, termios_sem, route_lock)
>>
>>
>>> > -> #1 (&port->buf.lock/1){+.+...}:
>>> >        [<ffffffff813f0acf>] lock_acquire+0x19f/0x3c0
>>> > kernel/locking/lockdep.c:3585
>>> >        [<     inline     >] __mutex_lock_common kernel/locking/mutex.c:518
>>> >        [<ffffffff85c86ba6>] mutex_lock_nested+0xb6/0x940
>>> > kernel/locking/mutex.c:618
>>> >        [<ffffffff82bc77ff>] n_tracerouter_open+0x1f/0x210
>>> > drivers/tty/n_tracerouter.c:75
>>> >        [<ffffffff82bacd78>] tty_ldisc_open.isra.2+0x78/0xd0
>>> > drivers/tty/tty_ldisc.c:447
>>> >        [<ffffffff82bad43a>] tty_set_ldisc+0x1ca/0xa30
>>> > drivers/tty/tty_ldisc.c:567
>>> >        [<     inline     >] tiocsetd drivers/tty/tty_io.c:2650
>>> >        [<ffffffff82b9483a>] tty_ioctl+0xb2a/0x2160 drivers/tty/tty_io.c:2883
>>> >        [<     inline     >] vfs_ioctl fs/ioctl.c:43
>>> >        [<ffffffff81750d41>] do_vfs_ioctl+0x681/0xe40 fs/ioctl.c:607
>>> >        [<     inline     >] SYSC_ioctl fs/ioctl.c:622
>>> >        [<ffffffff8175158f>] SyS_ioctl+0x8f/0xc0 fs/ioctl.c:613
>>> >        [<ffffffff85c8eb36>] entry_SYSCALL_64_fastpath+0x16/0x7a
>>> > arch/x86/entry/entry_64.S:185
>>
>> This is data being received by the new line discipline.
>>
>>         (buf->lock, routelock)
>>
>>> >
>>> > -> #0 (routelock){+.+...}:
>>> >        [<     inline     >] check_prev_add kernel/locking/lockdep.c:1853
>>> >        [<     inline     >] check_prevs_add kernel/locking/lockdep.c:1958
>>> >        [<     inline     >] validate_chain kernel/locking/lockdep.c:2144
>>> >        [<ffffffff813ee02e>] __lock_acquire+0x345e/0x3ca0
>>> > kernel/locking/lockdep.c:3206
>>> >        [<ffffffff813f0acf>] lock_acquire+0x19f/0x3c0
>>> > kernel/locking/lockdep.c:3585
>>> >        [<     inline     >] __mutex_lock_common kernel/locking/mutex.c:518
>>> >        [<ffffffff85c86ba6>] mutex_lock_nested+0xb6/0x940
>>> > kernel/locking/mutex.c:618
>>> >        [<ffffffff82bc77c0>] n_tracerouter_receivebuf+0x20/0x40
>>> > drivers/tty/n_tracerouter.c:175
>>> >        [<     inline     >] receive_buf drivers/tty/tty_buffer.c:454
>>> >        [<ffffffff82bafc34>] flush_to_ldisc+0x584/0x7f0
>>> > drivers/tty/tty_buffer.c:517
>>> >        [<ffffffff8133833c>] process_one_work+0x76c/0x13e0
>>> > kernel/workqueue.c:2030
>>> >        [<ffffffff81339093>] worker_thread+0xe3/0xe90 kernel/workqueue.c:2162
>>> >        [<ffffffff8134b63f>] kthread+0x23f/0x2d0 drivers/block/aoe/aoecmd.c:1303
>>> >        [<ffffffff85c8eeef>] ret_from_fork+0x3f/0x70
>>> > arch/x86/entry/entry_64.S:468
>>> >
>>
>> The lock inversion the log shows seems to be a problem in n_tty not in
>> the tracerouter code.
>>
>> However that seems to be
>>
>> tty_set_ldisc to N_TTY
>>         takes tty lock
>>         takes tty_ldisc lock
>>         down termios_rwsem (R)
>>         tty->ops->set_ldisc
>>         down termios rwsem (W)
>>
>> verus
>>
>> receive_driver_bufs
>>         buf->lock
>>         termios rwsem (R)
>>
>>
>> which also looks fine
>>
>> So I think it's just a false report caused by other changes in the tty
>> layer, and nothing to do with the tracerouter code at all.
>
>
> Thanks for looking into this.
>
> The report says:
>
>        CPU0                    CPU1
>        ----                    ----
>   lock(&buf->lock);
>                                lock(&o_tty->termios_rwsem/1);
>                                lock(&buf->lock);
>   lock(routelock);
>
> I don't see routelock in your stacks.
> But I also I don't understand why this is a deadlock. I would
> understand if one thread takes A then B; while another takes B then A.
> But here are 3 non-circular lock acquisitions. Does it have something
> to do with spinlocks vs mutex/rwsem?

+Peter, Ingo, can you please suggest a way to annotate this locking
pattern to avoid lockdep false positive?
It is cause by the fact that old and new ldisc locks are aliased?