[BUG][AX25] 2.6.28.5 "inconsistent lock state" (2 CPUs / SMP enabled)

[BUG][AX25] 2.6.28.5 "inconsistent lock state" (2 CPUs / SMP enabled)

[Jann Traschewski]

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

Hi,

the AX.25 code has still some problems with SMP and locking. I turned on
lock debugging on my machine with a lot of AX.25 traffic. Although it did
take serveral days until I got this:

=================================
[ INFO: inconsistent lock state ]
2.6.28.5-dg8ngn #1
---------------------------------
inconsistent {softirq-on-R} -> {in-softirq-W} usage.
swapper/0 [HC0[0]:SC1[2]:HE1:SE0] takes:
 (clock-AF_AX25){-+-?}, at: [<f859ed33>] ax25_destroy_socket+0xb6/0x1c4
[ax25]
{softirq-on-R} state was registered at:
  [<c013a751>] __lock_acquire+0x4e4/0x65e
  [<c0124d14>] local_bh_enable+0xa5/0xa9
  [<c013a914>] lock_acquire+0x49/0x61
  [<c025a221>] sock_def_wakeup+0x11/0x3d
  [<c02ca449>] _read_lock+0x19/0x24
  [<c025a221>] sock_def_wakeup+0x11/0x3d
  [<c025a221>] sock_def_wakeup+0x11/0x3d
  [<f859fb9c>] ax25_release+0x17e/0x1ab [ax25]
  [<c025847f>] sock_release+0x11/0x59
  [<c0258883>] sock_close+0x19/0x1c
  [<c0165ced>] __fput+0xbe/0x169
  [<c0163a43>] filp_close+0x4d/0x53
  [<c0121df6>] put_files_struct+0x5f/0xa7
  [<c0122ddc>] do_exit+0x187/0x669
  [<c0103840>] restore_nocheck_notrace+0x0/0xe
  [<c012331a>] do_group_exit+0x5c/0x85
  [<c0123350>] sys_exit_group+0xd/0x10
  [<c01037f6>] syscall_call+0x7/0xb
  [<ffffffff>] 0xffffffff
irq event stamp: 369633930
hardirqs last  enabled at (369633930): [<c02ca650>]
_spin_unlock_irqrestore+0x34/0x39
hardirqs last disabled at (369633929): [<c02ca595>]
_spin_lock_irqsave+0xc/0x31
softirqs last  enabled at (369633898): [<c01245e4>] do_softirq+0x37/0x4d
softirqs last disabled at (369633911): [<c01245e4>] do_softirq+0x37/0x4d

other info that might help us debug this:
1 lock held by swapper/0:
 #0:  (slock-AF_AX25){-+..}, at: [<f859dbfb>]
ax25_std_heartbeat_expiry+0x16/0xbb [ax25]

stack backtrace:
Pid: 0, comm: swapper Not tainted 2.6.28.5-dg8ngn #1
Call Trace:
 [<c01381f4>] print_usage_bug+0x13c/0x145
 [<c0138cb9>] mark_lock+0x33e/0x7bc
 [<c013a6d6>] __lock_acquire+0x469/0x65e
 [<c013a914>] lock_acquire+0x49/0x61
 [<f859ed33>] ax25_destroy_socket+0xb6/0x1c4 [ax25]
 [<c02ca3d2>] _write_lock_bh+0x1e/0x29
 [<f859ed33>] ax25_destroy_socket+0xb6/0x1c4 [ax25]
 [<f859ed33>] ax25_destroy_socket+0xb6/0x1c4 [ax25]
 [<f859e2ee>] ax25_heartbeat_expiry+0x0/0x29 [ax25]
 [<f859dc30>] ax25_std_heartbeat_expiry+0x4b/0xbb [ax25]
 [<c01278ca>] run_timer_softirq+0xf6/0x14b
 [<c01244ff>] __do_softirq+0x82/0x130
 [<c01245e4>] do_softirq+0x37/0x4d
 [<c010f8f9>] smp_apic_timer_interrupt+0x6e/0x78
 [<c0104455>] apic_timer_interrupt+0x2d/0x34
 [<c0108e76>] default_idle+0x2f/0x4c
 [<c0102561>] cpu_idle+0x63/0x77

Greetings,
Jann
DG8NGN


--
Jann Traschewski, Drosselstr.1, D-90513 Zirndorf, Germany
Tel.: +49-911-696971, Mobile: +49-170-1045937, E-Mail: jann@gmx.de
Ham: DG8NGN / DB0VOX, http://www.qsl.net/dg8ngn, ICQ UIN: 4130182 
 

[-- Attachment #2: smime.p7s --]
[-- Type: application/x-pkcs7-signature, Size: 3161 bytes --]

Re: [BUG][AX25] 2.6.28.5 "inconsistent lock state" (2 CPUs / SMP enabled)

[Jarek Poplawski]

On 03-05-2009 10:06, Jann Traschewski wrote:
> Hi,
> 
> the AX.25 code has still some problems with SMP and locking. I turned on
> lock debugging on my machine with a lot of AX.25 traffic. Although it did
> take serveral days until I got this:
> 
> =================================
> [ INFO: inconsistent lock state ]
> 2.6.28.5-dg8ngn #1
> ---------------------------------
> inconsistent {softirq-on-R} -> {in-softirq-W} usage.
> swapper/0 [HC0[0]:SC1[2]:HE1:SE0] takes:
>  (clock-AF_AX25){-+-?}, at: [<f859ed33>] ax25_destroy_socket+0xb6/0x1c4
> [ax25]
> {softirq-on-R} state was registered at:
>   [<c013a751>] __lock_acquire+0x4e4/0x65e
>   [<c0124d14>] local_bh_enable+0xa5/0xa9
>   [<c013a914>] lock_acquire+0x49/0x61
>   [<c025a221>] sock_def_wakeup+0x11/0x3d
>   [<c02ca449>] _read_lock+0x19/0x24
>   [<c025a221>] sock_def_wakeup+0x11/0x3d
>   [<c025a221>] sock_def_wakeup+0x11/0x3d
>   [<f859fb9c>] ax25_release+0x17e/0x1ab [ax25]
>   [<c025847f>] sock_release+0x11/0x59
>   [<c0258883>] sock_close+0x19/0x1c
...

Hi,

Could you try this patch?

Thanks,
Jarek P.
---

 net/ax25/af_ax25.c |   17 +++++++++++++++--
 1 files changed, 15 insertions(+), 2 deletions(-)

diff --git a/net/ax25/af_ax25.c b/net/ax25/af_ax25.c
index fd9d06f..f2fec78 100644
--- a/net/ax25/af_ax25.c
+++ b/net/ax25/af_ax25.c
@@ -314,8 +314,21 @@ void ax25_destroy_socket(ax25_cb *ax25)
 				/* A pending connection */
 				ax25_cb *sax25 = ax25_sk(skb->sk);
 
-				/* Queue the unaccepted socket for death */
-				sock_orphan(skb->sk);
+				/*
+				 * Queue the unaccepted socket for death.
+				 * Btw., it was never grafted, so sock_orphan()
+				 * is unnecessary.
+				 */
+				if (unlikely(skb->sk->sk_socket)) {
+					/*
+					 * This is old code, so let's leave it
+					 * for some time for debugging.
+					 */
+					sock_orphan(skb->sk);
+					WARN_ON_ONCE(1);
+				} else {
+					sock_set_flag(skb->sk, SOCK_DEAD);
+				}
 
 				/* 9A4GL: hack to release unaccepted sockets */
 				skb->sk->sk_state = TCP_LISTEN;

Re: [BUG][AX25] 2.6.28.5 "inconsistent lock state" (2 CPUs / SMPenabled)

[Jann Traschewski]

Thanks. Patch applied. It could take a long time until the problem will
occur again...

> -----Ursprüngliche Nachricht-----
> Von: Jarek Poplawski [mailto:jarkao2@gmail.com] 
> Gesendet: Montag, 4. Mai 2009 09:32
> An: Jann Traschewski
> Cc: netdev@vger.kernel.org
> Betreff: Re: [BUG][AX25] 2.6.28.5 "inconsistent lock state" 
> (2 CPUs / SMPenabled)
> 
> On 03-05-2009 10:06, Jann Traschewski wrote:
> > Hi,
> > 
> > the AX.25 code has still some problems with SMP and 
> locking. I turned 
> > on lock debugging on my machine with a lot of AX.25 
> traffic. Although 
> > it did take serveral days until I got this:
> > 
> > =================================
> > [ INFO: inconsistent lock state ]
> > 2.6.28.5-dg8ngn #1
> > ---------------------------------
> > inconsistent {softirq-on-R} -> {in-softirq-W} usage.
> > swapper/0 [HC0[0]:SC1[2]:HE1:SE0] takes:
> >  (clock-AF_AX25){-+-?}, at: [<f859ed33>] 
> > ax25_destroy_socket+0xb6/0x1c4 [ax25] {softirq-on-R} state was 
> > registered at:
> >   [<c013a751>] __lock_acquire+0x4e4/0x65e
> >   [<c0124d14>] local_bh_enable+0xa5/0xa9
> >   [<c013a914>] lock_acquire+0x49/0x61
> >   [<c025a221>] sock_def_wakeup+0x11/0x3d
> >   [<c02ca449>] _read_lock+0x19/0x24
> >   [<c025a221>] sock_def_wakeup+0x11/0x3d
> >   [<c025a221>] sock_def_wakeup+0x11/0x3d
> >   [<f859fb9c>] ax25_release+0x17e/0x1ab [ax25]
> >   [<c025847f>] sock_release+0x11/0x59
> >   [<c0258883>] sock_close+0x19/0x1c
> ...
> 
> Hi,
> 
> Could you try this patch?
> 
> Thanks,
> Jarek P.
> ---
> 
>  net/ax25/af_ax25.c |   17 +++++++++++++++--
>  1 files changed, 15 insertions(+), 2 deletions(-)
> 
> diff --git a/net/ax25/af_ax25.c b/net/ax25/af_ax25.c index 
> fd9d06f..f2fec78 100644
> --- a/net/ax25/af_ax25.c
> +++ b/net/ax25/af_ax25.c
> @@ -314,8 +314,21 @@ void ax25_destroy_socket(ax25_cb *ax25)
>  				/* A pending connection */
>  				ax25_cb *sax25 = ax25_sk(skb->sk);
>  
> -				/* Queue the unaccepted socket 
> for death */
> -				sock_orphan(skb->sk);
> +				/*
> +				 * Queue the unaccepted socket 
> for death.
> +				 * Btw., it was never grafted, 
> so sock_orphan()
> +				 * is unnecessary.
> +				 */
> +				if (unlikely(skb->sk->sk_socket)) {
> +					/*
> +					 * This is old code, so 
> let's leave it
> +					 * for some time for debugging.
> +					 */
> +					sock_orphan(skb->sk);
> +					WARN_ON_ONCE(1);
> +				} else {
> +					sock_set_flag(skb->sk, 
> SOCK_DEAD);
> +				}
>  
>  				/* 9A4GL: hack to release 
> unaccepted sockets */
>  				skb->sk->sk_state = TCP_LISTEN;