3.4+ tty lockdep trace

3.4+ tty lockdep trace

[Dave Jones]

>From v3.4-4413-gfb09baf

[   43.374948] =============================================
[   43.374991] [ INFO: possible recursive locking detected ]
[   43.375035] 3.4.0+ #24 Not tainted
[   43.375065] ---------------------------------------------
[   43.375108] sshd/639 is trying to acquire lock:
[   43.375157]  (&tty->legacy_mutex){+.+.+.}, at: [<ffffffff81656d57>] tty_lock+0x37/0x80
[   43.375216] 
[   43.375216] but task is already holding lock:
[   43.375268]  (&tty->legacy_mutex){+.+.+.}, at: [<ffffffff81656d57>] tty_lock+0x37/0x80
[   43.375327] 
[   43.375327] other info that might help us debug this:
[   43.375378]  Possible unsafe locking scenario:
[   43.375378] 
[   43.375425]        CPU0
[   43.375447]        ----
[   43.375471]   lock(&tty->legacy_mutex);
[   43.375504]   lock(&tty->legacy_mutex);
[   43.375536] 
[   43.375536]  *** DEADLOCK ***
[   43.375536] 
[   43.375583]  May be due to missing lock nesting notation
[   43.375583] 
[   43.375637] 2 locks held by sshd/639:
[   43.375675]  #0:  (tty_mutex){+.+.+.}, at: [<ffffffff813b0243>] tty_release+0x1c3/0x5d0
[   43.375740]  #1:  (&tty->legacy_mutex){+.+.+.}, at: [<ffffffff81656d57>] tty_lock+0x37/0x80
[   43.375802] 
[   43.375802] stack backtrace:
[   43.375841] Pid: 639, comm: sshd Not tainted 3.4.0+ #24
[   43.375882] Call Trace:
[   43.377572]  [<ffffffff810b4604>] __lock_acquire+0x1584/0x1aa0
[   43.379286]  [<ffffffff810b51e2>] lock_acquire+0x92/0x1f0
[   43.380995]  [<ffffffff81656d57>] ? tty_lock+0x37/0x80
[   43.382700]  [<ffffffff816534f1>] mutex_lock_nested+0x71/0x3b0
[   43.384403]  [<ffffffff81656d57>] ? tty_lock+0x37/0x80
[   43.386094]  [<ffffffff81085521>] ? get_parent_ip+0x11/0x50
[   43.387794]  [<ffffffff81656d57>] ? tty_lock+0x37/0x80
[   43.389480]  [<ffffffff8165a68d>] ? sub_preempt_count+0x6d/0xd0
[   43.391176]  [<ffffffff813b0243>] ? tty_release+0x1c3/0x5d0
[   43.393003]  [<ffffffff81656d57>] tty_lock+0x37/0x80
[   43.394867]  [<ffffffff81656dc3>] tty_lock_pair+0x23/0x5c
[   43.396671]  [<ffffffff813b024e>] tty_release+0x1ce/0x5d0
[   43.398462]  [<ffffffff811a765c>] fput+0x12c/0x300
[   43.400292]  [<ffffffff811a23a9>] filp_close+0x69/0xa0
[   43.402084]  [<ffffffff811a2f2d>] sys_close+0xad/0x1a0
[   43.403871]  [<ffffffff8165e652>] system_call_fastpath+0x16/0x1b

Re: 3.4+ tty lockdep trace

[Ming Lei]

Hi Dave,

On Wed, May 23, 2012 at 8:26 AM, Dave Jones <davej@redhat.com> wrote:
> From v3.4-4413-gfb09baf
>
> [   43.374948] =============================================
> [   43.374991] [ INFO: possible recursive locking detected ]
> [   43.375035] 3.4.0+ #24 Not tainted
> [   43.375065] ---------------------------------------------
> [   43.375108] sshd/639 is trying to acquire lock:
> [   43.375157]  (&tty->legacy_mutex){+.+.+.}, at: [<ffffffff81656d57>] tty_lock+0x37/0x80
> [   43.375216]
> [   43.375216] but task is already holding lock:
> [   43.375268]  (&tty->legacy_mutex){+.+.+.}, at: [<ffffffff81656d57>] tty_lock+0x37/0x80
> [   43.375327]
> [   43.375327] other info that might help us debug this:
> [   43.375378]  Possible unsafe locking scenario:
> [   43.375378]
> [   43.375425]        CPU0
> [   43.375447]        ----
> [   43.375471]   lock(&tty->legacy_mutex);
> [   43.375504]   lock(&tty->legacy_mutex);
> [   43.375536]
> [   43.375536]  *** DEADLOCK ***
> [   43.375536]
> [   43.375583]  May be due to missing lock nesting notation
> [   43.375583]
> [   43.375637] 2 locks held by sshd/639:
> [   43.375675]  #0:  (tty_mutex){+.+.+.}, at: [<ffffffff813b0243>] tty_release+0x1c3/0x5d0
> [   43.375740]  #1:  (&tty->legacy_mutex){+.+.+.}, at: [<ffffffff81656d57>] tty_lock+0x37/0x80
> [   43.375802]
> [   43.375802] stack backtrace:
> [   43.375841] Pid: 639, comm: sshd Not tainted 3.4.0+ #24
> [   43.375882] Call Trace:
> [   43.377572]  [<ffffffff810b4604>] __lock_acquire+0x1584/0x1aa0
> [   43.379286]  [<ffffffff810b51e2>] lock_acquire+0x92/0x1f0
> [   43.380995]  [<ffffffff81656d57>] ? tty_lock+0x37/0x80
> [   43.382700]  [<ffffffff816534f1>] mutex_lock_nested+0x71/0x3b0
> [   43.384403]  [<ffffffff81656d57>] ? tty_lock+0x37/0x80
> [   43.386094]  [<ffffffff81085521>] ? get_parent_ip+0x11/0x50
> [   43.387794]  [<ffffffff81656d57>] ? tty_lock+0x37/0x80
> [   43.389480]  [<ffffffff8165a68d>] ? sub_preempt_count+0x6d/0xd0
> [   43.391176]  [<ffffffff813b0243>] ? tty_release+0x1c3/0x5d0
> [   43.393003]  [<ffffffff81656d57>] tty_lock+0x37/0x80
> [   43.394867]  [<ffffffff81656dc3>] tty_lock_pair+0x23/0x5c
> [   43.396671]  [<ffffffff813b024e>] tty_release+0x1ce/0x5d0
> [   43.398462]  [<ffffffff811a765c>] fput+0x12c/0x300
> [   43.400292]  [<ffffffff811a23a9>] filp_close+0x69/0xa0
> [   43.402084]  [<ffffffff811a2f2d>] sys_close+0xad/0x1a0
> [   43.403871]  [<ffffffff8165e652>] system_call_fastpath+0x16/0x1b

We have one patch to address the problem, could you test it from the link below?

        http://marc.info/?l=linux-kernel&m=133765211309247&w=2


Thanks,
-- 
Ming Lei

Re: 3.4+ tty lockdep trace

[Dave Jones]

On Wed, May 23, 2012 at 09:06:22AM +0800, Ming Lei wrote:

 > > [   43.375802] stack backtrace:
 > > [   43.375841] Pid: 639, comm: sshd Not tainted 3.4.0+ #24
 > > [   43.375882] Call Trace:
 > > [   43.377572]  [<ffffffff810b4604>] __lock_acquire+0x1584/0x1aa0
 > > [   43.379286]  [<ffffffff810b51e2>] lock_acquire+0x92/0x1f0
 > > [   43.380995]  [<ffffffff81656d57>] ? tty_lock+0x37/0x80
 > > [   43.382700]  [<ffffffff816534f1>] mutex_lock_nested+0x71/0x3b0
 > > [   43.384403]  [<ffffffff81656d57>] ? tty_lock+0x37/0x80
 > > [   43.386094]  [<ffffffff81085521>] ? get_parent_ip+0x11/0x50
 > > [   43.387794]  [<ffffffff81656d57>] ? tty_lock+0x37/0x80
 > > [   43.389480]  [<ffffffff8165a68d>] ? sub_preempt_count+0x6d/0xd0
 > > [   43.391176]  [<ffffffff813b0243>] ? tty_release+0x1c3/0x5d0
 > > [   43.393003]  [<ffffffff81656d57>] tty_lock+0x37/0x80
 > > [   43.394867]  [<ffffffff81656dc3>] tty_lock_pair+0x23/0x5c
 > > [   43.396671]  [<ffffffff813b024e>] tty_release+0x1ce/0x5d0
 > > [   43.398462]  [<ffffffff811a765c>] fput+0x12c/0x300
 > > [   43.400292]  [<ffffffff811a23a9>] filp_close+0x69/0xa0
 > > [   43.402084]  [<ffffffff811a2f2d>] sys_close+0xad/0x1a0
 > > [   43.403871]  [<ffffffff8165e652>] system_call_fastpath+0x16/0x1b
 > 
 > We have one patch to address the problem, could you test it from the link below?
 > 
 >         http://marc.info/?l=linux-kernel&m=133765211309247&w=2

Yes, that seems to fix it. Thanks.

	Dave

Re: 3.4+ tty lockdep trace

[Dave Jones]

A different one. This time with devpts. (With the patch Ming Lei pointed to on top of Linus current)

	Dave

 ======================================================
 [ INFO: possible circular locking dependency detected ]
 3.4.0+ #25 Not tainted
 -------------------------------------------------------
 sshd/632 is trying to acquire lock:
  (devpts_mutex){+.+.+.}, at: [<ffffffff813b9846>] pty_close+0x156/0x180
 
 but task is already holding lock:
  (&tty->legacy_mutex){+.+.+.}, at: [<ffffffff81656cb2>] tty_lock_nested+0x42/0x90
 
 which lock already depends on the new lock.
 
 
 the existing dependency chain (in reverse order) is:
 
 -> #1 (&tty->legacy_mutex){+.+.+.}:
        [<ffffffff810b51e2>] lock_acquire+0x92/0x1f0
        [<ffffffff816534f1>] mutex_lock_nested+0x71/0x3b0
        [<ffffffff81656cb2>] tty_lock_nested+0x42/0x90
        [<ffffffff81656d10>] tty_lock+0x10/0x20
        [<ffffffff813afe8f>] tty_init_dev+0x6f/0x140
        [<ffffffff813b9946>] ptmx_open+0xa6/0x180
        [<ffffffff811aa2fb>] chrdev_open+0x9b/0x1b0
        [<ffffffff811a289b>] __dentry_open+0x26b/0x380
        [<ffffffff811a3d64>] nameidata_to_filp+0x74/0x80
        [<ffffffff811b5af8>] do_last+0x468/0x900
        [<ffffffff811b60a2>] path_openat+0xd2/0x3f0
        [<ffffffff811b64e1>] do_filp_open+0x41/0xa0
        [<ffffffff811a3e5d>] do_sys_open+0xed/0x1c0
        [<ffffffff811a3f51>] sys_open+0x21/0x30
        [<ffffffff8165e6d2>] system_call_fastpath+0x16/0x1b
 
 -> #0 (devpts_mutex){+.+.+.}:
        [<ffffffff810b43ae>] __lock_acquire+0x132e/0x1aa0
        [<ffffffff810b51e2>] lock_acquire+0x92/0x1f0
        [<ffffffff816534f1>] mutex_lock_nested+0x71/0x3b0
        [<ffffffff813b9846>] pty_close+0x156/0x180
        [<ffffffff813b0203>] tty_release+0x183/0x5d0
        [<ffffffff811a765c>] fput+0x12c/0x300
        [<ffffffff811a23a9>] filp_close+0x69/0xa0
        [<ffffffff811a2f2d>] sys_close+0xad/0x1a0
        [<ffffffff8165e6d2>] system_call_fastpath+0x16/0x1b
 
 other info that might help us debug this:
 
  Possible unsafe locking scenario:
 
        CPU0                    CPU1
        ----                    ----
   lock(&tty->legacy_mutex);
                                lock(devpts_mutex);
                                lock(&tty->legacy_mutex);
   lock(devpts_mutex);
 
  *** DEADLOCK ***
 
 1 lock held by sshd/632:
  #0:  (&tty->legacy_mutex){+.+.+.}, at: [<ffffffff81656cb2>] tty_lock_nested+0x42/0x90
 
 stack backtrace:
 Pid: 632, comm: sshd Not tainted 3.4.0+ #25
 Call Trace:
  [<ffffffff8164a64a>] print_circular_bug+0x1fb/0x20c
  [<ffffffff810b43ae>] __lock_acquire+0x132e/0x1aa0
  [<ffffffff810b51e2>] lock_acquire+0x92/0x1f0
  [<ffffffff813b9846>] ? pty_close+0x156/0x180
  [<ffffffff816534f1>] mutex_lock_nested+0x71/0x3b0
  [<ffffffff813b9846>] ? pty_close+0x156/0x180
  [<ffffffff8165a70d>] ? sub_preempt_count+0x6d/0xd0
  [<ffffffff813b9846>] ? pty_close+0x156/0x180
  [<ffffffff81656bd2>] ? _raw_spin_unlock_irqrestore+0x42/0x80
  [<ffffffff8107d9c3>] ? __wake_up+0x53/0x70
  [<ffffffff813b9846>] pty_close+0x156/0x180
  [<ffffffff813b0203>] tty_release+0x183/0x5d0
  [<ffffffff811c5670>] ? vfsmount_lock_local_unlock_cpu+0x70/0x70
  [<ffffffff811a765c>] fput+0x12c/0x300
  [<ffffffff811a23a9>] filp_close+0x69/0xa0
  [<ffffffff811a2f2d>] sys_close+0xad/0x1a0
  [<ffffffff8165e6d2>] system_call_fastpath+0x16/0x1b

Re: 3.4+ tty lockdep trace

[Ming Lei]

On Wed, May 23, 2012 at 10:02 AM, Dave Jones <davej@redhat.com> wrote:
> A different one. This time with devpts. (With the patch Ming Lei pointed to on top of Linus current)

It is another one, I saw it too when disconnecting a ssh shell and keep one
console shell.

It need some tty knowledge to fix this one, so maybe tty guys can handle it.

Thanks,
--
Ming Lei

>
>        Dave
>
>  ======================================================
>  [ INFO: possible circular locking dependency detected ]
>  3.4.0+ #25 Not tainted
>  -------------------------------------------------------
>  sshd/632 is trying to acquire lock:
>  (devpts_mutex){+.+.+.}, at: [<ffffffff813b9846>] pty_close+0x156/0x180
>
>  but task is already holding lock:
>  (&tty->legacy_mutex){+.+.+.}, at: [<ffffffff81656cb2>] tty_lock_nested+0x42/0x90
>
>  which lock already depends on the new lock.
>
>
>  the existing dependency chain (in reverse order) is:
>
>  -> #1 (&tty->legacy_mutex){+.+.+.}:
>        [<ffffffff810b51e2>] lock_acquire+0x92/0x1f0
>        [<ffffffff816534f1>] mutex_lock_nested+0x71/0x3b0
>        [<ffffffff81656cb2>] tty_lock_nested+0x42/0x90
>        [<ffffffff81656d10>] tty_lock+0x10/0x20
>        [<ffffffff813afe8f>] tty_init_dev+0x6f/0x140
>        [<ffffffff813b9946>] ptmx_open+0xa6/0x180
>        [<ffffffff811aa2fb>] chrdev_open+0x9b/0x1b0
>        [<ffffffff811a289b>] __dentry_open+0x26b/0x380
>        [<ffffffff811a3d64>] nameidata_to_filp+0x74/0x80
>        [<ffffffff811b5af8>] do_last+0x468/0x900
>        [<ffffffff811b60a2>] path_openat+0xd2/0x3f0
>        [<ffffffff811b64e1>] do_filp_open+0x41/0xa0
>        [<ffffffff811a3e5d>] do_sys_open+0xed/0x1c0
>        [<ffffffff811a3f51>] sys_open+0x21/0x30
>        [<ffffffff8165e6d2>] system_call_fastpath+0x16/0x1b
>
>  -> #0 (devpts_mutex){+.+.+.}:
>        [<ffffffff810b43ae>] __lock_acquire+0x132e/0x1aa0
>        [<ffffffff810b51e2>] lock_acquire+0x92/0x1f0
>        [<ffffffff816534f1>] mutex_lock_nested+0x71/0x3b0
>        [<ffffffff813b9846>] pty_close+0x156/0x180
>        [<ffffffff813b0203>] tty_release+0x183/0x5d0
>        [<ffffffff811a765c>] fput+0x12c/0x300
>        [<ffffffff811a23a9>] filp_close+0x69/0xa0
>        [<ffffffff811a2f2d>] sys_close+0xad/0x1a0
>        [<ffffffff8165e6d2>] system_call_fastpath+0x16/0x1b
>
>  other info that might help us debug this:
>
>  Possible unsafe locking scenario:
>
>        CPU0                    CPU1
>        ----                    ----
>   lock(&tty->legacy_mutex);
>                                lock(devpts_mutex);
>                                lock(&tty->legacy_mutex);
>   lock(devpts_mutex);
>
>  *** DEADLOCK ***
>
>  1 lock held by sshd/632:
>  #0:  (&tty->legacy_mutex){+.+.+.}, at: [<ffffffff81656cb2>] tty_lock_nested+0x42/0x90
>
>  stack backtrace:
>  Pid: 632, comm: sshd Not tainted 3.4.0+ #25
>  Call Trace:
>  [<ffffffff8164a64a>] print_circular_bug+0x1fb/0x20c
>  [<ffffffff810b43ae>] __lock_acquire+0x132e/0x1aa0
>  [<ffffffff810b51e2>] lock_acquire+0x92/0x1f0
>  [<ffffffff813b9846>] ? pty_close+0x156/0x180
>  [<ffffffff816534f1>] mutex_lock_nested+0x71/0x3b0
>  [<ffffffff813b9846>] ? pty_close+0x156/0x180
>  [<ffffffff8165a70d>] ? sub_preempt_count+0x6d/0xd0
>  [<ffffffff813b9846>] ? pty_close+0x156/0x180
>  [<ffffffff81656bd2>] ? _raw_spin_unlock_irqrestore+0x42/0x80
>  [<ffffffff8107d9c3>] ? __wake_up+0x53/0x70
>  [<ffffffff813b9846>] pty_close+0x156/0x180
>  [<ffffffff813b0203>] tty_release+0x183/0x5d0
>  [<ffffffff811c5670>] ? vfsmount_lock_local_unlock_cpu+0x70/0x70
>  [<ffffffff811a765c>] fput+0x12c/0x300
>  [<ffffffff811a23a9>] filp_close+0x69/0xa0
>  [<ffffffff811a2f2d>] sys_close+0xad/0x1a0
>  [<ffffffff8165e6d2>] system_call_fastpath+0x16/0x1b
>



-- 
Ming Lei

Re: 3.4+ tty lockdep trace

[Alan Cox]

On Tue, 22 May 2012 22:02:47 -0400
Dave Jones <davej@redhat.com> wrote:

> A different one. This time with devpts. (With the patch Ming Lei pointed to on top of Linus current)

That one loosk real - I'll go squash it tomorrow if I get time.

Alan

Re: 3.4+ tty lockdep trace

[Sasha Levin]

On Wed, May 23, 2012 at 3:06 AM, Ming Lei <tom.leiming@gmail.com> wrote:
> Hi Dave,
>
> On Wed, May 23, 2012 at 8:26 AM, Dave Jones <davej@redhat.com> wrote:
>> From v3.4-4413-gfb09baf
>>
>> [   43.374948] =============================================
>> [   43.374991] [ INFO: possible recursive locking detected ]
>> [   43.375035] 3.4.0+ #24 Not tainted
>> [   43.375065] ---------------------------------------------
>> [   43.375108] sshd/639 is trying to acquire lock:
>> [   43.375157]  (&tty->legacy_mutex){+.+.+.}, at: [<ffffffff81656d57>] tty_lock+0x37/0x80
>> [   43.375216]
>> [   43.375216] but task is already holding lock:
>> [   43.375268]  (&tty->legacy_mutex){+.+.+.}, at: [<ffffffff81656d57>] tty_lock+0x37/0x80
>> [   43.375327]
>> [   43.375327] other info that might help us debug this:
>> [   43.375378]  Possible unsafe locking scenario:
>> [   43.375378]
>> [   43.375425]        CPU0
>> [   43.375447]        ----
>> [   43.375471]   lock(&tty->legacy_mutex);
>> [   43.375504]   lock(&tty->legacy_mutex);
>> [   43.375536]
>> [   43.375536]  *** DEADLOCK ***
>> [   43.375536]
>> [   43.375583]  May be due to missing lock nesting notation
>> [   43.375583]
>> [   43.375637] 2 locks held by sshd/639:
>> [   43.375675]  #0:  (tty_mutex){+.+.+.}, at: [<ffffffff813b0243>] tty_release+0x1c3/0x5d0
>> [   43.375740]  #1:  (&tty->legacy_mutex){+.+.+.}, at: [<ffffffff81656d57>] tty_lock+0x37/0x80
>> [   43.375802]
>> [   43.375802] stack backtrace:
>> [   43.375841] Pid: 639, comm: sshd Not tainted 3.4.0+ #24
>> [   43.375882] Call Trace:
>> [   43.377572]  [<ffffffff810b4604>] __lock_acquire+0x1584/0x1aa0
>> [   43.379286]  [<ffffffff810b51e2>] lock_acquire+0x92/0x1f0
>> [   43.380995]  [<ffffffff81656d57>] ? tty_lock+0x37/0x80
>> [   43.382700]  [<ffffffff816534f1>] mutex_lock_nested+0x71/0x3b0
>> [   43.384403]  [<ffffffff81656d57>] ? tty_lock+0x37/0x80
>> [   43.386094]  [<ffffffff81085521>] ? get_parent_ip+0x11/0x50
>> [   43.387794]  [<ffffffff81656d57>] ? tty_lock+0x37/0x80
>> [   43.389480]  [<ffffffff8165a68d>] ? sub_preempt_count+0x6d/0xd0
>> [   43.391176]  [<ffffffff813b0243>] ? tty_release+0x1c3/0x5d0
>> [   43.393003]  [<ffffffff81656d57>] tty_lock+0x37/0x80
>> [   43.394867]  [<ffffffff81656dc3>] tty_lock_pair+0x23/0x5c
>> [   43.396671]  [<ffffffff813b024e>] tty_release+0x1ce/0x5d0
>> [   43.398462]  [<ffffffff811a765c>] fput+0x12c/0x300
>> [   43.400292]  [<ffffffff811a23a9>] filp_close+0x69/0xa0
>> [   43.402084]  [<ffffffff811a2f2d>] sys_close+0xad/0x1a0
>> [   43.403871]  [<ffffffff8165e652>] system_call_fastpath+0x16/0x1b
>
> We have one patch to address the problem, could you test it from the link below?
>
>        http://marc.info/?l=linux-kernel&m=133765211309247&w=2

I'm still seeing the warning with this patch:

[   83.032572] trinity (4823): Using mlock ulimits for SHM_HUGETLB is deprecated
[   83.060427] type=1400 audit(1.288:2): op=linkat action=denied
pid=4820 comm="trinity" path=2F7472696E6974792F746D702F03 dev="9p"
ino=104345
[   83.190164]
[   83.191412] =============================================
[   83.196004] [ INFO: possible recursive locking detected ]
[   83.196004] 3.4.0-next-20120523-sasha-00004-gc6cd556 #272 Tainted:
G        W
[   83.196004] ---------------------------------------------
[   83.196004] trinity/4823 is trying to acquire lock:
[   83.196004]  (&tty->legacy_mutex){+.+.+.}, at: [<ffffffff82f6a5db>]
tty_lock_nested+0x7b/0x90
[   83.196004]
[   83.196004] but task is already holding lock:
[   83.196004]  (&tty->legacy_mutex){+.+.+.}, at: [<ffffffff82f6a5db>]
tty_lock_nested+0x7b/0x90
[   83.196004]
[   83.196004] other info that might help us debug this:
[   83.196004]  Possible unsafe locking scenario:
[   83.196004]
[   83.196004]        CPU0
[   83.196004]        ----
[   83.196004]   lock(&tty->legacy_mutex);
[   83.196004]   lock(&tty->legacy_mutex);
[   83.196004]
[   83.196004]  *** DEADLOCK ***

Re: 3.4+ tty lockdep trace

[Alan Cox]

> I'm still seeing the warning with this patch:

Can you attach the trace that went with the trigger as well ?

Re: 3.4+ tty lockdep trace

[Sasha Levin]

[-- Attachment #1: Type: text/plain, Size: 222 bytes --]

On Thu, May 24, 2012 at 1:10 PM, Alan Cox <alan@lxorguk.ukuu.org.uk> wrote:
>> I'm still seeing the warning with this patch:
>
> Can you attach the trace that went with the trigger as well ?

Ofcourse, attached as a file.

[-- Attachment #2: tty_lockdep.txt --]
[-- Type: text/plain, Size: 6907 bytes --]

[   36.332022] ======================================================
[   36.333749] [ INFO: possible circular locking dependency detected ]
[   36.333749] 3.4.0-next-20120524-sasha-00002-g11dc651 #273 Tainted: G        W   
[   36.333749] -------------------------------------------------------
[   36.333749] trinity/4980 is trying to acquire lock:
[   36.333749]  (&tty->legacy_mutex){+.+.+.}, at: [<ffffffff82f71fdb>] tty_lock_nested+0x7b/0x90
[   36.333749] 
[   36.333749] but task is already holding lock:
[   36.333749]  (&tty->legacy_mutex/1){+.+...}, at: [<ffffffff82f71fdb>] tty_lock_nested+0x7b/0x90
[   36.333749] 
[   36.333749] which lock already depends on the new lock.
[   36.333749] 
[   36.333749] 
[   36.333749] the existing dependency chain (in reverse order) is:
[   36.333749] 
[   36.333749] -> #1 (&tty->legacy_mutex/1){+.+...}:
[   36.333749]        [<ffffffff8114a23e>] validate_chain+0x69e/0x790
[   36.333749]        [<ffffffff8114a753>] __lock_acquire+0x423/0x4c0
[   36.333749]        [<ffffffff8114a97a>] lock_acquire+0x18a/0x1e0
[   36.333749]        [<ffffffff82f6e410>] __mutex_lock_common+0x60/0x590
[   36.333749]        [<ffffffff82f6ea70>] mutex_lock_nested+0x40/0x50
[   36.333749]        [<ffffffff82f71fdb>] tty_lock_nested+0x7b/0x90
[   36.333749]        [<ffffffff82f7202e>] tty_lock_pair+0x2e/0x70
[   36.333749]        [<ffffffff81b0f962>] tty_release+0x182/0x4d0
[   36.333749]        [<ffffffff81232d4a>] __fput+0x11a/0x2c0
[   36.333749]        [<ffffffff81232f05>] fput+0x15/0x20
[   36.333749]        [<ffffffff8122f212>] filp_close+0x82/0xa0
[   36.333749]        [<ffffffff810d6514>] close_files+0x1b4/0x200
[   36.333749]        [<ffffffff810d6581>] put_files_struct+0x21/0x180
[   36.333749]        [<ffffffff810d672d>] exit_files+0x4d/0x60
[   36.333749]        [<ffffffff810d89f2>] do_exit+0x322/0x510
[   36.333749]        [<ffffffff810d8c81>] do_group_exit+0xa1/0xe0
[   36.333749]        [<ffffffff810ed5b8>] get_signal_to_deliver+0x4f8/0x580
[   36.333749]        [<ffffffff81065ae2>] do_signal+0x42/0x120
[   36.402106]        [<ffffffff81065c14>] do_notify_resume+0x54/0xb0
[   36.402106]        [<ffffffff82f723bb>] retint_signal+0x4d/0x92
[   36.402106] 
[   36.402106] -> #0 (&tty->legacy_mutex){+.+.+.}:
[   36.402106]        [<ffffffff811497ef>] check_prev_add+0x11f/0x4d0
[   36.402106]        [<ffffffff8114a23e>] validate_chain+0x69e/0x790
[   36.402106]        [<ffffffff8114a753>] __lock_acquire+0x423/0x4c0
[   36.402106]        [<ffffffff8114a97a>] lock_acquire+0x18a/0x1e0
[   36.402106]        [<ffffffff82f6e410>] __mutex_lock_common+0x60/0x590
[   36.402106]        [<ffffffff82f6ea70>] mutex_lock_nested+0x40/0x50
[   36.402106]        [<ffffffff82f71fdb>] tty_lock_nested+0x7b/0x90
[   36.402106]        [<ffffffff82f71ffb>] tty_lock+0xb/0x10
[   36.402106]        [<ffffffff81b155f7>] tty_ldisc_release+0x47/0xb0
[   36.402106]        [<ffffffff81b0fc33>] tty_release+0x453/0x4d0
[   36.402106]        [<ffffffff81232d4a>] __fput+0x11a/0x2c0
[   36.402106]        [<ffffffff81232f05>] fput+0x15/0x20
[   36.402106]        [<ffffffff8122f212>] filp_close+0x82/0xa0
[   36.402106]        [<ffffffff810d6514>] close_files+0x1b4/0x200
[   36.402106]        [<ffffffff810d6581>] put_files_struct+0x21/0x180
[   36.402106]        [<ffffffff810d672d>] exit_files+0x4d/0x60
[   36.402106]        [<ffffffff810d89f2>] do_exit+0x322/0x510
[   36.402106]        [<ffffffff810d8c81>] do_group_exit+0xa1/0xe0
[   36.402106]        [<ffffffff810ed5b8>] get_signal_to_deliver+0x4f8/0x580
[   36.402106]        [<ffffffff81065ae2>] do_signal+0x42/0x120
[   36.402106]        [<ffffffff81065c14>] do_notify_resume+0x54/0xb0
[   36.402106]        [<ffffffff82f723bb>] retint_signal+0x4d/0x92
[   36.402106] 
[   36.402106] other info that might help us debug this:
[   36.402106] 
[   36.402106]  Possible unsafe locking scenario:
[   36.402106] 
[   36.402106]        CPU0                    CPU1
[   36.402106]        ----                    ----
[   36.402106]   lock(&tty->legacy_mutex/1);
[   36.402106]                                lock(&tty->legacy_mutex);
[   36.402106]                                lock(&tty->legacy_mutex/1);
[   36.402106]   lock(&tty->legacy_mutex);
[   36.402106] 
[   36.402106]  *** DEADLOCK ***
[   36.402106] 
[   36.402106] 1 lock held by trinity/4980:
[   36.402106]  #0:  (&tty->legacy_mutex/1){+.+...}, at: [<ffffffff82f71fdb>] tty_lock_nested+0x7b/0x90
[   36.402106] 
[   36.402106] stack backtrace:
[   36.402106] Pid: 4980, comm: trinity Tainted: G        W    3.4.0-next-20120524-sasha-00002-g11dc651 #273
[   36.402106] Call Trace:
[   36.402106]  [<ffffffff811477d5>] print_circular_bug+0x105/0x120
[   36.402106]  [<ffffffff811497ef>] check_prev_add+0x11f/0x4d0
[   36.402106]  [<ffffffff8114a23e>] validate_chain+0x69e/0x790
[   36.402106]  [<ffffffff8111a5f8>] ? sched_clock_cpu+0x108/0x120
[   36.402106]  [<ffffffff8114a753>] __lock_acquire+0x423/0x4c0
[   36.402106]  [<ffffffff8114a97a>] lock_acquire+0x18a/0x1e0
[   36.402106]  [<ffffffff82f71fdb>] ? tty_lock_nested+0x7b/0x90
[   36.402106]  [<ffffffff82f6e410>] __mutex_lock_common+0x60/0x590
[   36.402106]  [<ffffffff82f71fdb>] ? tty_lock_nested+0x7b/0x90
[   36.402106]  [<ffffffff8114aea2>] ? __lock_release+0x1c2/0x1e0
[   36.402106]  [<ffffffff810f5240>] ? flush_scheduled_work+0x20/0x20
[   36.402106]  [<ffffffff82f71fdb>] ? tty_lock_nested+0x7b/0x90
[   36.402106]  [<ffffffff82f6ea70>] mutex_lock_nested+0x40/0x50
[   36.402106]  [<ffffffff82f71fdb>] tty_lock_nested+0x7b/0x90
[   36.402106]  [<ffffffff82f71ffb>] tty_lock+0xb/0x10
[   36.402106]  [<ffffffff81b155f7>] tty_ldisc_release+0x47/0xb0
[   36.402106]  [<ffffffff81b0fc33>] tty_release+0x453/0x4d0
[   36.402106]  [<ffffffff812836cb>] ? vfs_lock_file+0x3b/0x40
[   36.402106]  [<ffffffff81232d4a>] __fput+0x11a/0x2c0
[   36.402106]  [<ffffffff81232f05>] fput+0x15/0x20
[   36.402106]  [<ffffffff8122f212>] filp_close+0x82/0xa0
[   36.402106]  [<ffffffff810d6514>] close_files+0x1b4/0x200
[   36.402106]  [<ffffffff810d6360>] ? wait_task_stopped+0x3d0/0x3d0
[   36.402106]  [<ffffffff810d6725>] ? exit_files+0x45/0x60
[   36.402106]  [<ffffffff810d6581>] put_files_struct+0x21/0x180
[   36.402106]  [<ffffffff82f71a10>] ? _raw_spin_unlock+0x30/0x60
[   36.402106]  [<ffffffff810d672d>] exit_files+0x4d/0x60
[   36.402106]  [<ffffffff810d89f2>] do_exit+0x322/0x510
[   36.402106]  [<ffffffff810d8c81>] do_group_exit+0xa1/0xe0
[   36.402106]  [<ffffffff810ed5b8>] get_signal_to_deliver+0x4f8/0x580
[   36.402106]  [<ffffffff81065ae2>] do_signal+0x42/0x120
[   36.402106]  [<ffffffff81090000>] ? create_irq+0x10/0x30
[   36.402106]  [<ffffffff811ee78e>] ? might_fault+0x4e/0xa0
[   36.402106]  [<ffffffff82f7237f>] ? retint_signal+0x11/0x92
[   36.402106]  [<ffffffff81065c14>] do_notify_resume+0x54/0xb0
[   36.402106]  [<ffffffff82f723bb>] retint_signal+0x4d/0x92

Re: 3.4+ tty lockdep trace

[Sasha Levin]

On Thu, May 24, 2012 at 1:20 PM, Sasha Levin <levinsasha928@gmail.com> wrote:
> On Thu, May 24, 2012 at 1:10 PM, Alan Cox <alan@lxorguk.ukuu.org.uk> wrote:
>>> I'm still seeing the warning with this patch:
>>
>> Can you attach the trace that went with the trigger as well ?
>
> Ofcourse, attached as a file.

Heh, this was a different one as well. I'll try to get the one I got
in the morning again.

Re: 3.4+ tty lockdep trace

[Sasha Levin]

[-- Attachment #1: Type: text/plain, Size: 601 bytes --]

On Thu, May 24, 2012 at 1:21 PM, Sasha Levin <levinsasha928@gmail.com> wrote:
> On Thu, May 24, 2012 at 1:20 PM, Sasha Levin <levinsasha928@gmail.com> wrote:
>> On Thu, May 24, 2012 at 1:10 PM, Alan Cox <alan@lxorguk.ukuu.org.uk> wrote:
>>>> I'm still seeing the warning with this patch:
>>>
>>> Can you attach the trace that went with the trigger as well ?
>>
>> Ofcourse, attached as a file.
>
> Heh, this was a different one as well. I'll try to get the one I got
> in the morning again.

And here is the second one attached as well, so these are two
different warnings I get with the new version.

[-- Attachment #2: tty_lockdep2.txt --]
[-- Type: text/plain, Size: 3157 bytes --]

[   39.888115] =============================================
[   39.888115] [ INFO: possible recursive locking detected ]
[   39.888115] 3.4.0-next-20120524-sasha-00002-g11dc651 #273 Tainted: G        W   
[   39.888115] ---------------------------------------------
[   39.888115] trinity/4980 is trying to acquire lock:
[   39.888115]  (&tty->legacy_mutex){+.+.+.}, at: [<ffffffff82f71fdb>] tty_lock_nested+0x7b/0x90
[   39.888115] 
[   39.888115] but task is already holding lock:
[   39.888115]  (&tty->legacy_mutex){+.+.+.}, at: [<ffffffff82f71fdb>] tty_lock_nested+0x7b/0x90
[   39.888115] 
[   39.888115] other info that might help us debug this:
[   39.888115]  Possible unsafe locking scenario:
[   39.888115] 
[   39.888115]        CPU0
[   39.888115]        ----
[   39.888115]   lock(&tty->legacy_mutex);
[   39.888115]   lock(&tty->legacy_mutex);
[   39.888115] 
[   39.888115]  *** DEADLOCK ***
[   39.888115] 
[   39.888115]  May be due to missing lock nesting notation
[   39.888115] 
[   39.888115] 1 lock held by trinity/4980:
[   39.888115]  #0:  (&tty->legacy_mutex){+.+.+.}, at: [<ffffffff82f71fdb>] tty_lock_nested+0x7b/0x90
[   39.888115] 
[   39.888115] stack backtrace:
[   39.888115] Pid: 4980, comm: trinity Tainted: G        W    3.4.0-next-20120524-sasha-00002-g11dc651 #273
[   39.888115] Call Trace:
[   39.888115]  [<ffffffff81148019>] print_deadlock_bug+0x119/0x140
[   39.888115]  [<ffffffff8114a18e>] validate_chain+0x5ee/0x790
[   39.888115]  [<ffffffff8111a5f8>] ? sched_clock_cpu+0x108/0x120
[   39.973550]  [<ffffffff8114a753>] __lock_acquire+0x423/0x4c0
[   39.973550]  [<ffffffff8114a97a>] lock_acquire+0x18a/0x1e0
[   39.973550]  [<ffffffff82f71fdb>] ? tty_lock_nested+0x7b/0x90
[   39.973550]  [<ffffffff82f6e410>] __mutex_lock_common+0x60/0x590
[   39.973550]  [<ffffffff82f71fdb>] ? tty_lock_nested+0x7b/0x90
[   39.973550]  [<ffffffff8114aea2>] ? __lock_release+0x1c2/0x1e0
[   39.973550]  [<ffffffff810f5240>] ? flush_scheduled_work+0x20/0x20
[   39.973550]  [<ffffffff82f71fdb>] ? tty_lock_nested+0x7b/0x90
[   39.973550]  [<ffffffff82f6ea70>] mutex_lock_nested+0x40/0x50
[   39.973550]  [<ffffffff82f71fdb>] tty_lock_nested+0x7b/0x90
[   39.973550]  [<ffffffff82f71ffb>] tty_lock+0xb/0x10
[   39.973550]  [<ffffffff81b155f7>] tty_ldisc_release+0x47/0xb0
[   39.973550]  [<ffffffff81b0fc33>] tty_release+0x453/0x4d0
[   39.973550]  [<ffffffff81232d4a>] __fput+0x11a/0x2c0
[   39.973550]  [<ffffffff81232f05>] fput+0x15/0x20
[   39.973550]  [<ffffffff8122f212>] filp_close+0x82/0xa0
[   39.973550]  [<ffffffff810d6514>] close_files+0x1b4/0x200
[   39.973550]  [<ffffffff810d6360>] ? wait_task_stopped+0x3d0/0x3d0
[   39.973550]  [<ffffffff810d6725>] ? exit_files+0x45/0x60
[   39.973550]  [<ffffffff810d6581>] put_files_struct+0x21/0x180
[   39.973550]  [<ffffffff82f71a10>] ? _raw_spin_unlock+0x30/0x60
[   39.973550]  [<ffffffff810d672d>] exit_files+0x4d/0x60
[   39.973550]  [<ffffffff810d89f2>] do_exit+0x322/0x510
[   39.973550]  [<ffffffff810d8c81>] do_group_exit+0xa1/0xe0
[   39.973550]  [<ffffffff810d8cd2>] sys_exit_group+0x12/0x20
[   39.973550]  [<ffffffff82f72bb9>] system_call_fastpath+0x16/0x1b

Re: 3.4+ tty lockdep trace

[Alan Cox]

On Thu, 24 May 2012 13:24:56 +0200
Sasha Levin <levinsasha928@gmail.com> wrote:

> On Thu, May 24, 2012 at 1:21 PM, Sasha Levin
> <levinsasha928@gmail.com> wrote:
> > On Thu, May 24, 2012 at 1:20 PM, Sasha Levin
> > <levinsasha928@gmail.com> wrote:
> >> On Thu, May 24, 2012 at 1:10 PM, Alan Cox
> >> <alan@lxorguk.ukuu.org.uk> wrote:
> >>>> I'm still seeing the warning with this patch:
> >>>
> >>> Can you attach the trace that went with the trigger as well ?
> >>
> >> Ofcourse, attached as a file.
> >
> > Heh, this was a different one as well. I'll try to get the one I got
> > in the morning again.
> 
> And here is the second one attached as well, so these are two
> different warnings I get with the new version.


I'm somewhat baffled by this one. Can lockdep be fooled by an object
being freed and reallocated at the same address, Is there any markup
that should be present to avoid that ?

Alan

Re: 3.4+ tty lockdep trace

[Steven Rostedt]

On Thu, May 24, 2012 at 03:54:57PM +0100, Alan Cox wrote:
> On Thu, 24 May 2012 13:24:56 +0200
> Sasha Levin <levinsasha928@gmail.com> wrote:
> > 
> > And here is the second one attached as well, so these are two
> > different warnings I get with the new version.
> 
> 
> I'm somewhat baffled by this one. Can lockdep be fooled by an object
> being freed and reallocated at the same address, Is there any markup
> that should be present to avoid that ?

Sasha,

Did you apply Ming's second patch. His first patch (the one referenced
in the email) didn't have the unlock fixup.

--Steve

Re: 3.4+ tty lockdep trace

[Sasha Levin]

On Fri, May 25, 2012 at 4:32 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
> On Thu, May 24, 2012 at 03:54:57PM +0100, Alan Cox wrote:
>> On Thu, 24 May 2012 13:24:56 +0200
>> Sasha Levin <levinsasha928@gmail.com> wrote:
>> >
>> > And here is the second one attached as well, so these are two
>> > different warnings I get with the new version.
>>
>>
>> I'm somewhat baffled by this one. Can lockdep be fooled by an object
>> being freed and reallocated at the same address, Is there any markup
>> that should be present to avoid that ?
>
> Sasha,
>
> Did you apply Ming's second patch. His first patch (the one referenced
> in the email) didn't have the unlock fixup.

Nope, I just got the first one.

What's the right patchset to use atm? I know about these patches from
Ming, and I see Alan sent out two patches yesterday. Which ones should
I use for testing?

Re: 3.4+ tty lockdep trace

[Ming Lei]

On Fri, May 25, 2012 at 4:07 PM, Sasha Levin <levinsasha928@gmail.com> wrote:
> On Fri, May 25, 2012 at 4:32 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
>> On Thu, May 24, 2012 at 03:54:57PM +0100, Alan Cox wrote:
>>> On Thu, 24 May 2012 13:24:56 +0200
>>> Sasha Levin <levinsasha928@gmail.com> wrote:
>>> >
>>> > And here is the second one attached as well, so these are two
>>> > different warnings I get with the new version.
>>>
>>>
>>> I'm somewhat baffled by this one. Can lockdep be fooled by an object
>>> being freed and reallocated at the same address, Is there any markup
>>> that should be present to avoid that ?
>>
>> Sasha,
>>
>> Did you apply Ming's second patch. His first patch (the one referenced
>> in the email) didn't have the unlock fixup.
>
> Nope, I just got the first one.
>
> What's the right patchset to use atm? I know about these patches from
> Ming, and I see Alan sent out two patches yesterday. Which ones should
> I use for testing?

You can try to apply my 2nd patch against Alan's two patches for the tests.


Thanks,
-- 
Ming Lei

Re: 3.4+ tty lockdep trace

[Sasha Levin]

[-- Attachment #1: Type: text/plain, Size: 1271 bytes --]

On Fri, May 25, 2012 at 10:30 AM, Ming Lei <tom.leiming@gmail.com> wrote:
> On Fri, May 25, 2012 at 4:07 PM, Sasha Levin <levinsasha928@gmail.com> wrote:
>> On Fri, May 25, 2012 at 4:32 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
>>> On Thu, May 24, 2012 at 03:54:57PM +0100, Alan Cox wrote:
>>>> On Thu, 24 May 2012 13:24:56 +0200
>>>> Sasha Levin <levinsasha928@gmail.com> wrote:
>>>> >
>>>> > And here is the second one attached as well, so these are two
>>>> > different warnings I get with the new version.
>>>>
>>>>
>>>> I'm somewhat baffled by this one. Can lockdep be fooled by an object
>>>> being freed and reallocated at the same address, Is there any markup
>>>> that should be present to avoid that ?
>>>
>>> Sasha,
>>>
>>> Did you apply Ming's second patch. His first patch (the one referenced
>>> in the email) didn't have the unlock fixup.
>>
>> Nope, I just got the first one.
>>
>> What's the right patchset to use atm? I know about these patches from
>> Ming, and I see Alan sent out two patches yesterday. Which ones should
>> I use for testing?
>
> You can try to apply my 2nd patch against Alan's two patches for the tests.

Applying Ming's patch over Alan's 2 patches from yesterday, I'm still
seeing two lockdep warnings. Full trace attached.

[-- Attachment #2: tty_lockdep3.txt --]
[-- Type: text/plain, Size: 10366 bytes --]

[   40.627460] 
[   40.628014] =============================================
[   40.628014] [ INFO: possible recursive locking detected ]
[   40.628014] 3.4.0-next-20120524-sasha-00005-g9d5c83d #286 Tainted: G        W   
[   40.628014] ---------------------------------------------
[   40.628014] trinity-child1/4949 is trying to acquire lock:
[   40.628014]  (&tty->legacy_mutex){+.+.+.}, at: [<ffffffff82f71ffb>] tty_lock_nested+0x7b/0x90
[   40.628014] 
[   40.628014] but task is already holding lock:
[   40.628014]  (&tty->legacy_mutex){+.+.+.}, at: [<ffffffff82f71ffb>] tty_lock_nested+0x7b/0x90
[   40.628014] 
[   40.628014] other info that might help us debug this:
[   40.628014]  Possible unsafe locking scenario:
[   40.628014] 
[   40.628014]        CPU0
[   40.628014]        ----
[   40.628014]   lock(&tty->legacy_mutex);
[   40.628014]   lock(&tty->legacy_mutex);
[   40.628014] 
[   40.628014]  *** DEADLOCK ***
[   40.628014] 
[   40.628014]  May be due to missing lock nesting notation
[   40.628014] 
[   40.628014] 1 lock held by trinity-child1/4949:
[   40.628014]  #0:  (&tty->legacy_mutex){+.+.+.}, at: [<ffffffff82f71ffb>] tty_lock_nested+0x7b/0x90
[   40.628014] 
[   40.628014] stack backtrace:
[   40.628014] Pid: 4949, comm: trinity-child1 Tainted: G        W    3.4.0-next-20120524-sasha-00005-g9d5c83d #286
[   40.628014] Call Trace:
[   40.628014]  [<ffffffff81148019>] print_deadlock_bug+0x119/0x140
[   40.628014]  [<ffffffff8114a18e>] validate_chain+0x5ee/0x790
[   40.628014]  [<ffffffff8111a5f8>] ? sched_clock_cpu+0x108/0x120
[   40.628014]  [<ffffffff8114a753>] __lock_acquire+0x423/0x4c0
[   40.628014]  [<ffffffff8114444e>] ? put_lock_stats+0xe/0x40
[   40.628014]  [<ffffffff8114a97a>] lock_acquire+0x18a/0x1e0
[   40.628014]  [<ffffffff82f71ffb>] ? tty_lock_nested+0x7b/0x90
[   40.628014]  [<ffffffff810f5240>] ? flush_scheduled_work+0x20/0x20
[   40.628014]  [<ffffffff82f6e430>] __mutex_lock_common+0x60/0x590
[   40.628014]  [<ffffffff82f71ffb>] ? tty_lock_nested+0x7b/0x90
[   40.628014]  [<ffffffff810f5405>] ? flush_work_sync+0x45/0x90
[   40.628014]  [<ffffffff8114aea2>] ? __lock_release+0x1c2/0x1e0
[   40.628014]  [<ffffffff810f5240>] ? flush_scheduled_work+0x20/0x20
[   40.628014]  [<ffffffff82f71ffb>] ? tty_lock_nested+0x7b/0x90
[   40.628014]  [<ffffffff82f6ea90>] mutex_lock_nested+0x40/0x50
[   40.628014]  [<ffffffff82f71ffb>] tty_lock_nested+0x7b/0x90
[   40.628014]  [<ffffffff82f72082>] tty_lock_pair+0x62/0x70
[   40.628014]  [<ffffffff81b1563a>] tty_ldisc_release+0x4a/0xb0
[   40.628014]  [<ffffffff81b1568b>] tty_ldisc_release+0x9b/0xb0
[   40.628014]  [<ffffffff81b0fc73>] tty_release+0x453/0x4d0
[   40.628014]  [<ffffffff82f6e365>] ? __mutex_unlock_slowpath+0x1a5/0x200
[   40.628014]  [<ffffffff82f6e3c9>] ? mutex_unlock+0x9/0x10
[   40.628014]  [<ffffffff82f720e4>] ? tty_unlock+0x54/0x60
[   40.628014]  [<ffffffff81232d9a>] __fput+0x11a/0x2c0
[   40.628014]  [<ffffffff81232f55>] fput+0x15/0x20
[   40.628014]  [<ffffffff8122f262>] filp_close+0x82/0xa0
[   40.823224]  [<ffffffff810d6514>] close_files+0x1b4/0x200
[   40.823224]  [<ffffffff810d6360>] ? wait_task_stopped+0x3d0/0x3d0
[   40.823224]  [<ffffffff810d6725>] ? exit_files+0x45/0x60
[   40.823224]  [<ffffffff810d6581>] put_files_struct+0x21/0x180
[   40.823224]  [<ffffffff82f71a30>] ? _raw_spin_unlock+0x30/0x60
[   40.823224]  [<ffffffff810d672d>] exit_files+0x4d/0x60
[   40.823224]  [<ffffffff810d89f2>] do_exit+0x322/0x510
[   40.823224]  [<ffffffff810d8c81>] do_group_exit+0xa1/0xe0
[   40.823224]  [<ffffffff810d8cd2>] sys_exit_group+0x12/0x20
[   40.823224]  [<ffffffff82f72bf9>] system_call_fastpath+0x16/0x1b

===

[   40.941023] ======================================================
[   40.941691] [ INFO: possible circular locking dependency detected ]
[   40.941691] 3.4.0-next-20120524-sasha-00005-g9d5c83d #286 Tainted: G        W   
[   40.941691] -------------------------------------------------------
[   40.941691] trinity-child1/4988 is trying to acquire lock:
[   40.941691]  (&tty->legacy_mutex){+.+.+.}, at: [<ffffffff82f71ffb>] tty_lock_nested+0x7b/0x90
[   40.941691] 
[   40.941691] but task is already holding lock:
[   40.941691]  (&tty->legacy_mutex/1){+.+...}, at: [<ffffffff82f71ffb>] tty_lock_nested+0x7b/0x90
[   40.941691] 
[   40.941691] which lock already depends on the new lock.
[   40.941691] 
[   40.941691] 
[   40.941691] the existing dependency chain (in reverse order) is:
[   40.941691] 
[   40.941691] -> #1 (&tty->legacy_mutex/1){+.+...}:
[   40.941691]        [<ffffffff8114a23e>] validate_chain+0x69e/0x790
[   40.941691]        [<ffffffff8114a753>] __lock_acquire+0x423/0x4c0
[   40.941691]        [<ffffffff8114a97a>] lock_acquire+0x18a/0x1e0
[   40.941691]        [<ffffffff82f6e430>] __mutex_lock_common+0x60/0x590
[   40.941691]        [<ffffffff82f6ea90>] mutex_lock_nested+0x40/0x50
[   40.941691]        [<ffffffff82f71ffb>] tty_lock_nested+0x7b/0x90
[   40.941691]        [<ffffffff82f72082>] tty_lock_pair+0x62/0x70
[   40.941691]        [<ffffffff81b0f9a2>] tty_release+0x182/0x4d0
[   40.941691]        [<ffffffff81232d9a>] __fput+0x11a/0x2c0
[   40.941691]        [<ffffffff81232f55>] fput+0x15/0x20
[   40.941691]        [<ffffffff8122f262>] filp_close+0x82/0xa0
[   40.941691]        [<ffffffff810d6514>] close_files+0x1b4/0x200
[   40.941691]        [<ffffffff810d6581>] put_files_struct+0x21/0x180
[   40.941691]        [<ffffffff810d672d>] exit_files+0x4d/0x60
[   40.941691]        [<ffffffff810d89f2>] do_exit+0x322/0x510
[   40.941691]        [<ffffffff810d8c81>] do_group_exit+0xa1/0xe0
[   40.941691]        [<ffffffff810d8cd2>] sys_exit_group+0x12/0x20
[   40.941691]        [<ffffffff82f72bf9>] system_call_fastpath+0x16/0x1b
[   40.941691] 
[   40.941691] -> #0 (&tty->legacy_mutex){+.+.+.}:
[   40.941691]        [<ffffffff811497ef>] check_prev_add+0x11f/0x4d0
[   40.941691]        [<ffffffff8114a23e>] validate_chain+0x69e/0x790
[   40.941691]        [<ffffffff8114a753>] __lock_acquire+0x423/0x4c0
[   40.941691]        [<ffffffff8114a97a>] lock_acquire+0x18a/0x1e0
[   40.941691]        [<ffffffff82f6e430>] __mutex_lock_common+0x60/0x590
[   40.941691]        [<ffffffff82f6ea90>] mutex_lock_nested+0x40/0x50
[   40.941691]        [<ffffffff82f71ffb>] tty_lock_nested+0x7b/0x90
[   40.941691]        [<ffffffff82f72082>] tty_lock_pair+0x62/0x70
[   40.941691]        [<ffffffff81b1563a>] tty_ldisc_release+0x4a/0xb0
[   40.941691]        [<ffffffff81b1568b>] tty_ldisc_release+0x9b/0xb0
[   40.941691]        [<ffffffff81b0fc73>] tty_release+0x453/0x4d0
[   40.941691]        [<ffffffff81232d9a>] __fput+0x11a/0x2c0
[   40.941691]        [<ffffffff81232f55>] fput+0x15/0x20
[   40.941691]        [<ffffffff8122f262>] filp_close+0x82/0xa0
[   40.941691]        [<ffffffff810d6514>] close_files+0x1b4/0x200
[   40.941691]        [<ffffffff810d6581>] put_files_struct+0x21/0x180
[   40.941691]        [<ffffffff810d672d>] exit_files+0x4d/0x60
[   40.941691]        [<ffffffff810d89f2>] do_exit+0x322/0x510
[   40.941691]        [<ffffffff810d8c81>] do_group_exit+0xa1/0xe0
[   40.941691]        [<ffffffff810d8cd2>] sys_exit_group+0x12/0x20
[   40.941691]        [<ffffffff82f72bf9>] system_call_fastpath+0x16/0x1b
[   40.941691] 
[   40.941691] other info that might help us debug this:
[   40.941691] 
[   40.941691]  Possible unsafe locking scenario:
[   40.941691] 
[   40.941691]        CPU0                    CPU1
[   40.941691]        ----                    ----
[   40.941691]   lock(&tty->legacy_mutex/1);
[   40.941691]                                lock(&tty->legacy_mutex);
[   40.941691]                                lock(&tty->legacy_mutex/1);
[   40.941691]   lock(&tty->legacy_mutex);
[   40.941691] 
[   40.941691]  *** DEADLOCK ***
[   40.941691] 
[   40.941691] 1 lock held by trinity-child1/4988:
[   40.941691]  #0:  (&tty->legacy_mutex/1){+.+...}, at: [<ffffffff82f71ffb>] tty_lock_nested+0x7b/0x90
[   40.941691] 
[   40.941691] stack backtrace:
[   40.941691] Pid: 4988, comm: trinity-child1 Tainted: G        W    3.4.0-next-20120524-sasha-00005-g9d5c83d #286
[   40.941691] Call Trace:
[   40.941691]  [<ffffffff811477d5>] print_circular_bug+0x105/0x120
[   40.941691]  [<ffffffff811497ef>] check_prev_add+0x11f/0x4d0
[   40.941691]  [<ffffffff82f71b4b>] ? _raw_spin_unlock_irq+0x2b/0x80
[   40.941691]  [<ffffffff8114a23e>] validate_chain+0x69e/0x790
[   40.941691]  [<ffffffff8111a5f8>] ? sched_clock_cpu+0x108/0x120
[   40.941691]  [<ffffffff8114a753>] __lock_acquire+0x423/0x4c0
[   40.941691]  [<ffffffff8114444e>] ? put_lock_stats+0xe/0x40
[   40.941691]  [<ffffffff8114a97a>] lock_acquire+0x18a/0x1e0
[   40.941691]  [<ffffffff82f71ffb>] ? tty_lock_nested+0x7b/0x90
[   40.941691]  [<ffffffff810f5240>] ? flush_scheduled_work+0x20/0x20
[   40.941691]  [<ffffffff82f6e430>] __mutex_lock_common+0x60/0x590
[   40.941691]  [<ffffffff82f71ffb>] ? tty_lock_nested+0x7b/0x90
[   40.941691]  [<ffffffff810f5405>] ? flush_work_sync+0x45/0x90
[   40.941691]  [<ffffffff8114aea2>] ? __lock_release+0x1c2/0x1e0
[   40.941691]  [<ffffffff810f5240>] ? flush_scheduled_work+0x20/0x20
[   40.941691]  [<ffffffff82f71ffb>] ? tty_lock_nested+0x7b/0x90
[   40.941691]  [<ffffffff82f6ea90>] mutex_lock_nested+0x40/0x50
[   40.941691]  [<ffffffff82f71ffb>] tty_lock_nested+0x7b/0x90
[   40.941691]  [<ffffffff82f72082>] tty_lock_pair+0x62/0x70
[   40.941691]  [<ffffffff81b1563a>] tty_ldisc_release+0x4a/0xb0
[   40.941691]  [<ffffffff81b1568b>] tty_ldisc_release+0x9b/0xb0
[   40.941691]  [<ffffffff81b0fc73>] tty_release+0x453/0x4d0
[   40.941691]  [<ffffffff81232d9a>] __fput+0x11a/0x2c0
[   40.941691]  [<ffffffff81232f55>] fput+0x15/0x20
[   40.941691]  [<ffffffff8122f262>] filp_close+0x82/0xa0
[   40.941691]  [<ffffffff810d6514>] close_files+0x1b4/0x200
[   40.941691]  [<ffffffff810d6360>] ? wait_task_stopped+0x3d0/0x3d0
[   40.941691]  [<ffffffff810d6725>] ? exit_files+0x45/0x60
[   40.941691]  [<ffffffff810d6581>] put_files_struct+0x21/0x180
[   40.941691]  [<ffffffff82f71a30>] ? _raw_spin_unlock+0x30/0x60
[   40.941691]  [<ffffffff810d672d>] exit_files+0x4d/0x60
[   40.941691]  [<ffffffff810d89f2>] do_exit+0x322/0x510
[   40.941691]  [<ffffffff810d8c81>] do_group_exit+0xa1/0xe0
[   40.941691]  [<ffffffff810d8cd2>] sys_exit_group+0x12/0x20
[   40.941691]  [<ffffffff82f72bf9>] system_call_fastpath+0x16/0x1b

Re: 3.4+ tty lockdep trace

[Alan Cox]

> Applying Ming's patch over Alan's 2 patches from yesterday, I'm still
> seeing two lockdep warnings. Full trace attached.

In that code path we've just succesfully done

	tty_lock_pair(tty, o_tty)

(no warning issued)

We've then called into tty_ldisc_release which has done

	tty_unlock_pair(tty, o_tty);

and then

	tty_lock_pair(tty, o_tty);

which can't error unless our locking hosed

and at that point we then then do a recursive

	tty_ldisc_release(o_tty, NULL)

which embarrassingly already has a comment above it I put there saying


        /* This will need doing differently if we need to lock */


Let me go rewrite that particular routine to make sense with the
locking in place.