Re: tty: deadlock between n_tracerouter_receivebuf and flush_to_ldisc

[Dmitry Vyukov]

On Thu, Feb 4, 2016 at 1:39 PM, Dmitry Vyukov <dvyukov@xxxxxxxxxx> wrote:
> On Wed, Feb 3, 2016 at 8:09 PM, Peter Hurley <peter@xxxxxxxxxxxxxxxxxx> wrote:
>> On 02/03/2016 09:32 AM, Dmitry Vyukov wrote:
>>> On Wed, Feb 3, 2016 at 5:24 AM, Peter Hurley <peter@xxxxxxxxxxxxxxxxxx> wrote:
>>>> Hi Dmitry,
>>>>
>>>> On 01/21/2016 09:43 AM, Peter Hurley wrote:
>>>>> On 01/21/2016 02:06 AM, Dmitry Vyukov wrote:
>>>>>> On Wed, Jan 20, 2016 at 5:08 PM, Peter Hurley <peter@xxxxxxxxxxxxxxxxxx> wrote:
>>>>>>> On 01/20/2016 05:02 AM, Peter Zijlstra wrote:
>>>>>>>> On Wed, Dec 30, 2015 at 11:44:01AM +0100, Dmitry Vyukov wrote:
>>>>>>>>> -> #3 (&buf->lock){+.+...}:
>>>>>>>>>        [<ffffffff813f0acf>] lock_acquire+0x19f/0x3c0 kernel/locking/lockdep.c:3585
>>>>>>>>>        [<     inline     >] __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:112
>>>>>>>>>        [<ffffffff85c8e790>] _raw_spin_lock_irqsave+0x50/0x70 kernel/locking/spinlock.c:159
>>>>>>>>>        [<ffffffff82b8c050>] tty_get_pgrp+0x20/0x80 drivers/tty/tty_io.c:2502
>>>>>>>>
>>>>>>>> So in any recent code that I look at this function tries to acquire
>>>>>>>> tty->ctrl_lock, not buf->lock. Am I missing something ?!
>>>>>>>
>>>>>>> Yes.
>>>>>>>
>>>>>>> The tty locks were annotated with __lockfunc so were being elided from lockdep
>>>>>>> stacktraces. Greg has a patch in his queue from me that removes the __lockfunc
>>>>>>> annotation ("tty: Remove __lockfunc annotation from tty lock functions").
>>>>>>>
>>>>>>> Unfortunately, I think syzkaller's post-processing stack trace isn't helping
>>>>>>> either, giving the impression that the stack is still inside tty_get_pgrp().
>>>>>>>
>>>>>>> It's not.
>>>>>>
>>>>>> I've got a new report on commit
>>>>>> a200dcb34693084e56496960d855afdeaaf9578f  (Jan 18).
>>>>>> Here is unprocessed version:
>>>>>> https://gist.githubusercontent.com/dvyukov/428a0c9bfaa867d8ce84/raw/0754db31668602ad07947f9964238b2f9cf63315/gistfile1.txt
>>>>>> and here is processed one:
>>>>>> https://gist.githubusercontent.com/dvyukov/42b874213de82d94c35e/raw/2bbced252035821243678de0112e2ed3a766fb5d/gistfile1.txt
>>>>>>
>>>>>> Peter, what exactly is wrong with the post-processed version?
>>>>>
>>>>> Yeah, ok, I assumed the problem with this report was post-processing
>>>>> because of the other report that had mixed-up info.
>>>>>
>>>>> However, the #3 stacktrace is obviously wrong, as others have already noted.
>>>>> Plus, the #1 stacktrace is wrong as well.
>>>>>
>>>>>> I would be interested in fixing the processing script.
>>>>>
>>>>> Not that it's related (since the original, not-edited report has bogus
>>>>> stacktraces), but how are you doing debug symbol lookup?
>>>>>
>>>>> Because below is not correct. Should be kernel/kthread.c:177 (or thereabouts)
>>>>>
>>>>>        [<ffffffff813b423f>] kthread+0x23f/0x2d0 drivers/block/aoe/aoecmd.c:1303
>>>>>
>>>>>
>>>>>> As far as I see it contains the same stacks just with line numbers and
>>>>>> inlined frames.
>>>>>
>>>>> Agree, now that I see the original report.
>>>>>
>>>>>> I am using a significantly different compilation mode
>>>>>> (kasan + kcov + very recent gcc), so nobody except me won't be able to
>>>>>> figure out line numbers based on offsets.
>>>>>
>>>>> Weird. Maybe something to do with the compiler.
>>>>>
>>>>> Can you get me the dmesg output running the patch below?
>>>>
>>>> Wondering if this is still the priority it was not so long ago?
>>>> If not, that's fine and I'll drop this from my followup list.
>>>
>>>
>>> Yes, it is still the priority for me.
>>> I've tried to apply your debugging patch, but I noticed that it prints
>>> dependencies stacks as it discovers them.
>>
>> Yeah, that's the point; I need to understand why lockdep doesn't
>> store the correct stack trace at dependency discovery.
>>
>> Since the correct stack trace will be printed instead, it will help
>> debug the lockdep problem.
>>
>> Hopefully, once the problem with the bad stacktraces are fixed, the
>> actual circular lock dependencies will be clear.
>>
>>> But in my setup I don't have
>>> all output from machine start (there is just too many of it).
>>
>> Kernel parameter:
>>
>>         log_buf_len=1G
>>
>>
>>> And I don't have a localized reproducer for this.
>>
>> I really just need the lockdep dependency stacks generated during boot,
>> and the ctrl+C in a terminal window to trigger one of the dependency
>> stacks.
>>
>>> I will try again.
>>
>> Ok.
>>
>>> Do you want me to debug with your "tty: Fix lock inversion in
>>> N_TRACEROUTER" patch applied or not (I still see slightly different
>>> deadlock reports with it)?
>>
>> Not.
>>
>> I think that probably does fix at least one circular dependency, but
>> I want to figure out the bad stack trace problem first.
>>
>> There's probably another circular dependency there, as indicated by
>> your other report.
>
>
> Here is debug output:
> https://gist.githubusercontent.com/dvyukov/b18181c849fdd3d51c80/raw/e91ead683fec020f64eed6750aa9f6347d43b9f9/gistfile1.txt
>
> In particular the ctrl+C dependency is:
>
>  new dependency:  (&o_tty->termios_rwsem/1){++++..} =>  (&buf->lock){+.+...}
> [  216.817400] Call Trace:
> [  216.817400]  [<ffffffff82be450d>] dump_stack+0x6f/0xa2
> [  216.817400]  [<ffffffff8145b149>] __lock_acquire+0x4859/0x5710
> [  216.817400]  [<ffffffff8145e61c>] lock_acquire+0x1dc/0x430
> [  216.817400]  [<ffffffff86656871>] mutex_lock_nested+0xb1/0xa50
> [  216.817400]  [<ffffffff82f9f08f>] tty_buffer_flush+0xbf/0x3c0
> [  216.817400]  [<ffffffff82fa330c>] pty_flush_buffer+0x5c/0x180
> [  216.817400]  [<ffffffff82f97a05>] tty_driver_flush_buffer+0x65/0x80
> [  216.817400]  [<ffffffff82f8d162>] isig+0x172/0x2c0
> [  216.817400]  [<ffffffff82f8fe52>] n_tty_receive_signal_char+0x22/0xf0
> [  216.817400]  [<ffffffff82f93a4e>] n_tty_receive_char_special+0x126e/0x2b30
> [  216.817400]  [<ffffffff82f96cb3>] n_tty_receive_buf_common+0x19a3/0x2400
> [  216.817400]  [<ffffffff82f97743>] n_tty_receive_buf2+0x33/0x40
> [  216.817400]  [<ffffffff82f9e83f>] flush_to_ldisc+0x3bf/0x7f0
> [  216.817400]  [<ffffffff813a3eb6>] process_one_work+0x796/0x1440
> [  216.817400]  [<ffffffff813a4c3b>] worker_thread+0xdb/0xfc0
> [  216.817400]  [<ffffffff813b7edf>] kthread+0x23f/0x2d0
> [  216.817400]  [<ffffffff866608ef>] ret_from_fork+0x3f/0x70
>
> While in report it still looks as:
>
> -> #3 (&buf->lock){+.+...}:
> [ 1544.187872]        [<ffffffff8145e61c>] lock_acquire+0x1dc/0x430
> [ 1544.187872]        [<ffffffff8665fecf>] _raw_spin_lock_irqsave+0x9f/0xd0
> [ 1544.187872]        [<ffffffff82f7c810>] tty_get_pgrp+0x20/0x80
> [ 1544.187872]        [<ffffffff82f8afca>] __isig+0x1a/0x50
> [ 1544.187872]        [<ffffffff82f8d09e>] isig+0xae/0x2c0
> [ 1544.187872]        [<ffffffff82f8fe52>] n_tty_receive_signal_char+0x22/0xf0
> [ 1544.187872]        [<ffffffff82f93a6d>]
> n_tty_receive_char_special+0x128d/0x2b30
> [ 1544.187872]        [<ffffffff82f96cb3>]
> n_tty_receive_buf_common+0x19a3/0x2400
> [ 1544.187872]        [<ffffffff82f97743>] n_tty_receive_buf2+0x33/0x40
> [ 1544.187872]        [<ffffffff82f9e83f>] flush_to_ldisc+0x3bf/0x7f0
> [ 1544.187872]        [<ffffffff813a3eb6>] process_one_work+0x796/0x1440
> [ 1544.187872]        [<ffffffff813a4c3b>] worker_thread+0xdb/0xfc0
> [ 1544.187872]        [<ffffffff813b7edf>] kthread+0x23f/0x2d0
> [ 1544.187872]        [<ffffffff866608ef>] ret_from_fork+0x3f/0x70
>
>
> It seems to me that tty_get_pgrp is red herring. Ctrl lock is not
> mentioned in reports, and isig indeed calls __isig/tty_get_pgrp just
> before tty_driver_flush_buffer, so it looks like stack unwinding bug.


Found a bug in lockdep. Yes, the first stack is correct, and the saved
stack is just a random, unrelated stack. Will mail a fix.