From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Message-ID: <4CA2EDA1.9050201@nokia.com> Date: Wed, 29 Sep 2010 11:41:21 +0400 From: Yuri Kululin MIME-Version: 1.0 To: "ext Gustavo F. Padovan" CC: linux-bluetooth@vger.kernel.org, "Gustavo F. Padovan" Subject: Re: [PATCH 4/6] Bluetooth: Fix inconsistent lock state with RFCOMM References: <1285376504-3541-1-git-send-email-gustavo@padovan.org> <1285376504-3541-2-git-send-email-gustavo@padovan.org> <1285376504-3541-3-git-send-email-gustavo@padovan.org> <1285376504-3541-4-git-send-email-gustavo@padovan.org> <1285376504-3541-5-git-send-email-gustavo@padovan.org> In-Reply-To: <1285376504-3541-5-git-send-email-gustavo@padovan.org> Content-Type: text/plain; charset=ISO-8859-1; format=flowed Sender: linux-bluetooth-owner@vger.kernel.org List-ID: ext Gustavo F. Padovan wrote: > From: Gustavo F. Padovan > > When receiving a rfcomm connection with the old dund deamon a > inconsistent lock state happens. That's because interrupts were already > disabled by l2cap_conn_start() when rfcomm_sk_state_change() try to lock > the spin_lock. > > As result we may have a inconsistent lock state for l2cap_conn_start() > after rfcomm_sk_state_change() calls bh_lock_sock() and disable interrupts > as well. > > [ 2833.151999] > [ 2833.151999] ================================= > [ 2833.151999] [ INFO: inconsistent lock state ] > [ 2833.151999] 2.6.36-rc3 #2 > [ 2833.151999] --------------------------------- > [ 2833.151999] inconsistent {IN-SOFTIRQ-W} -> {SOFTIRQ-ON-W} usage. > [ 2833.151999] krfcommd/2306 [HC0[0]:SC0[0]:HE1:SE1] takes: > [ 2833.151999] (slock-AF_BLUETOOTH){+.?...}, at: [] rfcomm_sk_state_change+0x46/0x170 [rfcomm] > [ 2833.151999] {IN-SOFTIRQ-W} state was registered at: > [ 2833.151999] [] __lock_acquire+0x5b6/0x1560 > [ 2833.151999] [] lock_acquire+0x5a/0x70 > [ 2833.151999] [] _raw_spin_lock+0x2c/0x40 > [ 2833.151999] [] l2cap_conn_start+0x92/0x640 [l2cap] > [ 2833.151999] [] l2cap_sig_channel+0x6bf/0x1320 [l2cap] > [ 2833.151999] [] l2cap_recv_frame+0x133/0x770 [l2cap] > [ 2833.151999] [] l2cap_recv_acldata+0x1cb/0x390 [l2cap] > [ 2833.151999] [] hci_rx_task+0x2ab/0x450 [bluetooth] > [ 2833.151999] [] tasklet_action+0xcb/0xe0 > [ 2833.151999] [] __do_softirq+0xae/0x150 > [ 2833.151999] [] call_softirq+0x1c/0x30 > [ 2833.151999] [] do_softirq+0x75/0xb0 > [ 2833.151999] [] irq_exit+0x8d/0xa0 > [ 2833.151999] [] smp_apic_timer_interrupt+0x6b/0xa0 > [ 2833.151999] [] apic_timer_interrupt+0x13/0x20 > [ 2833.151999] [] cpu_idle+0x5a/0xb0 > [ 2833.151999] [] rest_init+0xad/0xc0 > [ 2833.151999] [] start_kernel+0x2dd/0x2e8 > [ 2833.151999] [] x86_64_start_reservations+0xf6/0xfa > [ 2833.151999] [] x86_64_start_kernel+0xe4/0xeb > [ 2833.151999] irq event stamp: 731 > [ 2833.151999] hardirqs last enabled at (731): [] local_bh_enable_ip+0x82/0xe0 > [ 2833.151999] hardirqs last disabled at (729): [] __do_softirq+0xce/0x150 > [ 2833.151999] softirqs last enabled at (730): [] __do_softirq+0xfe/0x150 > [ 2833.151999] softirqs last disabled at (711): [] call_softirq+0x1c/0x30 > [ 2833.151999] > [ 2833.151999] other info that might help us debug this: > [ 2833.151999] 2 locks held by krfcommd/2306: > [ 2833.151999] #0: (rfcomm_mutex){+.+.+.}, at: [] rfcomm_run+0x174/0xb20 [rfcomm] > [ 2833.151999] #1: (&(&d->lock)->rlock){+.+...}, at: [] rfcomm_dlc_accept+0x53/0x100 [rfcomm] > [ 2833.151999] > [ 2833.151999] stack backtrace: > [ 2833.151999] Pid: 2306, comm: krfcommd Tainted: G W 2.6.36-rc3 #2 > [ 2833.151999] Call Trace: > [ 2833.151999] [] print_usage_bug+0x171/0x180 > [ 2833.151999] [] mark_lock+0x333/0x400 > [ 2833.151999] [] __lock_acquire+0x63a/0x1560 > [ 2833.151999] [] ? __lock_acquire+0xb25/0x1560 > [ 2833.151999] [] lock_acquire+0x5a/0x70 > [ 2833.151999] [] ? rfcomm_sk_state_change+0x46/0x170 [rfcomm] > [ 2833.151999] [] _raw_spin_lock+0x2c/0x40 > [ 2833.151999] [] ? rfcomm_sk_state_change+0x46/0x170 [rfcomm] > [ 2833.151999] [] rfcomm_sk_state_change+0x46/0x170 [rfcomm] > [ 2833.151999] [] rfcomm_dlc_accept+0x69/0x100 [rfcomm] > [ 2833.151999] [] rfcomm_check_accept+0x59/0xd0 [rfcomm] > [ 2833.151999] [] rfcomm_recv_frame+0x9fb/0x1320 [rfcomm] > [ 2833.151999] [] ? _raw_spin_unlock_irqrestore+0x3b/0x60 > [ 2833.151999] [] ? trace_hardirqs_on_caller+0x13d/0x180 > [ 2833.151999] [] ? trace_hardirqs_on+0xd/0x10 > [ 2833.151999] [] rfcomm_run+0x221/0xb20 [rfcomm] > [ 2833.151999] [] ? schedule+0x287/0x780 > [ 2833.151999] [] ? rfcomm_run+0x0/0xb20 [rfcomm] > [ 2833.151999] [] kthread+0x96/0xa0 > [ 2833.151999] [] kernel_thread_helper+0x4/0x10 > [ 2833.151999] [] ? restore_args+0x0/0x30 > [ 2833.151999] [] ? kthread+0x0/0xa0 > [ 2833.151999] [] ? kernel_thread_helper+0x0/0x10 > > Signed-off-by: Gustavo F. Padovan > --- > net/bluetooth/rfcomm/sock.c | 4 ++++ > 1 files changed, 4 insertions(+), 0 deletions(-) > > diff --git a/net/bluetooth/rfcomm/sock.c b/net/bluetooth/rfcomm/sock.c > index 44a6232..194b3a0 100644 > --- a/net/bluetooth/rfcomm/sock.c > +++ b/net/bluetooth/rfcomm/sock.c > @@ -82,11 +82,14 @@ static void rfcomm_sk_data_ready(struct rfcomm_dlc *d, struct sk_buff *skb) > static void rfcomm_sk_state_change(struct rfcomm_dlc *d, int err) > { > struct sock *sk = d->owner, *parent; > + unsigned long flags; > + > if (!sk) > return; > > BT_DBG("dlc %p state %ld err %d", d, d->state, err); > > + local_irq_save(flags); > bh_lock_sock(sk); > > if (err) > @@ -108,6 +111,7 @@ static void rfcomm_sk_state_change(struct rfcomm_dlc *d, int err) > } > > bh_unlock_sock(sk); > + local_irq_restore(flags); > > if (parent && sock_flag(sk, SOCK_ZAPPED)) { > /* We have to drop DLC lock here, otherwise I've faced with the similar warning and looks like this patch fixes the issue. [ 2917.827178] ================================= [ 2917.833068] [ INFO: inconsistent lock state ] [ 2917.837432] 2.6.32-09421-g65e7ba7 #54 [ 2917.841125] --------------------------------- [ 2917.845520] inconsistent {IN-SOFTIRQ-W} -> {SOFTIRQ-ON-W} usage. [ 2917.851562] krfcommd/1516 [HC0[0]:SC0[0]:HE1:SE1] takes: [ 2917.856903] (slock-AF_BLUETOOTH){+.?...}, at: [] rfcomm_sk_state_change+0x78/0x160 [rfcomm] [ 2917.866363] {IN-SOFTIRQ-W} state was registered at: [ 2917.871276] [] mark_lock+0x298/0x630 [ 2917.875946] [] __lock_acquire+0x5f4/0x175c [ 2917.881134] [] lock_acquire+0x68/0x7c [ 2917.885864] [] _spin_lock+0x48/0x58 [ 2917.890441] [] l2cap_conn_start+0x80/0x388 [l2cap] [ 2917.896362] [] l2cap_recv_frame+0x1c58/0x2fe0 [l2cap] [ 2917.902526] [] l2cap_recv_acldata+0x100/0x350 [l2cap] [ 2917.908691] [] hci_rx_task+0x244/0x478 [bluetooth] [ 2917.914642] [] tasklet_action+0x78/0xd8 [ 2917.919555] [] __do_softirq+0xa8/0x154 [ 2917.924407] [] irq_exit+0x60/0xb4 [ 2917.928802] [] asm_do_IRQ+0x78/0x90 [ 2917.933380] [] __irq_svc+0x50/0xbc [ 2917.937866] [] omap3_enter_idle_bm+0x1d0/0x238 [ 2917.943389] [] cpuidle_idle_call+0xb4/0x114 [ 2917.948669] [] cpu_idle+0x58/0xac [ 2917.953063] [] rest_init+0x70/0x84 [ 2917.957550] [] start_kernel+0x2b4/0x318 [ 2917.962493] [<80008034>] 0x80008034 [ 2917.966186] irq event stamp: 312 [ 2917.969421] hardirqs last enabled at (312): [] _spin_unlock_irqrestore+0x44/0x70 [ 2917.977844] hardirqs last disabled at (311): [] _spin_lock_irqsave+0x24/0x68 [ 2917.985809] softirqs last enabled at (261): [] __do_softirq+0x13c/0x154 [ 2917.993438] softirqs last disabled at (244): [] do_softirq+0x54/0x78 [ 2918.000732] [ 2918.000732] other info that might help us debug this: [ 2918.007293] 2 locks held by krfcommd/1516: [ 2918.011413] #0: (rfcomm_mutex){+.+.+.}, at: [] rfcomm_run+0x1f0/0xb00 [rfcomm] [ 2918.019805] #1: (&d->lock){+.+...}, at: [] rfcomm_run+0x61c/0xb00 [rfcomm] [ 2918.027832] [ 2918.027832] stack backtrace: [ 2918.032226] Backtrace: [ 2918.034729] [] (dump_backtrace+0x0/0x110) from [] (dump_stack+0x18/0x1c) [ 2918.043212] r7:dc8f6c00 r6:c0425252 r5:00000001 r4:00000001 [ 2918.048950] [] (dump_stack+0x0/0x1c) from [] (print_usage_bug+0x178/0x1bc) [ 2918.057617] [] (print_usage_bug+0x0/0x1bc) from [] (mark_lock+0x364/0x630) [ 2918.066284] [] (mark_lock+0x0/0x630) from [] (__lock_acquire+0x684/0x175c) [ 2918.074951] [] (__lock_acquire+0x0/0x175c) from [] (lock_acquire+0x68/0x7c) [ 2918.083709] [] (lock_acquire+0x0/0x7c) from [] (_spin_lock+0x48/0x58) [ 2918.091949] r7:dba9402c r6:dba5c3c0 r5:dba9402c r4:bf057b50 [ 2918.097717] [] (_spin_lock+0x0/0x58) from [] (rfcomm_sk_state_change+0x78/0x160 [rfcomm]) [ 2918.107696] r5:dba94000 r4:00000000 [ 2918.111358] [] (rfcomm_sk_state_change+0x0/0x160 [rfcomm]) from [] (rfcomm_run+0x634/0xb00 [rfcomm]) [ 2918.122283] r7:dba5c450 r6:dba5d6c0 r5:dba5c3c0 r4:dba5c430 [ 2918.128051] [] (rfcomm_run+0x0/0xb00 [rfcomm]) from [] (kthread+0x88/0x90) [ 2918.136749] [] (kthread+0x0/0x90) from [] (do_exit+0x0/0x678) [ 2918.144256] r7:00000000 r6:00000000 r5:00000000 r4:00000000 Thanks, Yuri K.