(irda) Badness in local_bh_enable at kernel/softirq.c:121
Subsystems (2)
Hi,
I've just been testing w83977af_ir with ircomm on a NetWinder (ARM) and a Nokia mobile phone, and, while closing down the connection by exiting minicom, I saw this which looks particularly evil. I'm not sure exactly when this occurred because I was running minicom over ssh.
ircomm_param_service_type(), services in common=04ircomm_param_service_type(), resulting service type=0x04ircomm_param_port_type(), port type=1ircomm_param_port_type(), port type=1ircomm_param_xon_xoff(), XON/XOFF = 0x11,0x13ircomm_param_enq_ack(), ENQ/ACK = 0x13,0x11ircomm_tty_check_modem_status()ircomm_tty_check_modem_status()ircomm_tty_check_modem_status()ircomm_tty_check_modem_status()ircomm_tty_close()ircomm_tty_shutdown()ircomm_tty_detach_cable()
Badness in local_bh_enable at kernel/softirq.c:121
[<c00429c4>] (local_bh_enable+0x0/0x84) from [<c014d1b4>] (dev_queue_xmit+0x108/0x20c)
[<c014d0ac>] (dev_queue_xmit+0x0/0x20c) from [<bf00ee68>] (irlap_send_data_primary_poll+0xdc/0x1c4 [irda]) [<bf00ed8c>] (irlap_send_data_primary_poll+0x0/0x1c4 [irda]) from [<bf00babc>] (irlap_state_xmit_p+0x1a4/0x308 [irda]) [<bf00b918>] (irlap_state_xmit_p+0x0/0x308 [irda]) from [<bf00a78c>] (irlap_do_event+0xd8/0x1f0 [irda]) [<bf00a6b4>] (irlap_do_event+0x0/0x1f0 [irda]) from [<bf008938>] (irlap_data_request+0x174/0x1a8 [irda]) [<bf0087c4>] (irlap_data_request+0x0/0x1a8 [irda]) from [<bf006f80>] (irlmp_state_dtr+0x17c/0x328 [irda]) [<bf006e04>] (irlmp_state_dtr+0x0/0x328 [irda]) from [<bf005fcc>] (irlmp_do_lsap_event+0xb8/0xe8 [irda]) [<bf005f14>] (irlmp_do_lsap_event+0x0/0xe8 [irda]) from [<bf003bc8>] (irlmp_disconnect_request+0x138/0x2f0 [irda]) [<bf003a90>] (irlmp_disconnect_request+0x0/0x2f0 [irda]) from [<bf0149bc>] (irttp_disconnect_request+0x220/0x274 [irda]) [<bf01479c>] (irttp_disconnect_request+0x0/0x274 [irda]) from [<bf035100>] (ircomm_state_conn+0xbc/0xf0 [ircomm]) [<bf035044>] (ircomm_state_conn+0x0/0xf0 [ircomm]) from [<bf0351a0>] (ircomm_do_event+0x6c/0x88 [ircomm]) [<bf035134>] (ircomm_do_event+0x0/0x88 [ircomm]) from [<bf034a40>] (ircomm_disconnect_request+0x94/0xc0 [ircomm]) [<bf0349ac>] (ircomm_disconnect_request+0x0/0xc0 [ircomm]) from [<bf03d838>] (ircomm_tty_state_ready+0x58/0xfc [ircomm_tty]) [<bf03d7e0>] (ircomm_tty_state_ready+0x0/0xfc [ircomm_tty]) from [<bf03d99c>] (ircomm_tty_do_event+0xc0/0xf4 [ircomm_tty]) [<bf03d8dc>] (ircomm_tty_do_event+0x0/0xf4 [ircomm_tty]) from [<bf03c4fc>] (ircomm_tty_detach_cable+0xcc/0x10c [ircomm_tty]) [<bf03c430>] (ircomm_tty_detach_cable+0x0/0x10c [ircomm_tty]) from [<bf03b5d8>] (ircomm_tty_shutdown+0x128/0x178 [ircomm_tty]) [<bf03b4b0>] (ircomm_tty_shutdown+0x0/0x178 [ircomm_tty]) from [<bf03a9c0>] (ircomm_tty_close+0x15c/0x240 [ircomm_tty]) [<bf03a864>] (ircomm_tty_close+0x0/0x240 [ircomm_tty]) from [<c00d7bd4>] (release_dev+0x1d8/0x5a4) [<c00d79fc>] (release_dev+0x0/0x5a4) from [<c00d831c>] (tty_release+0x14/0x1c)
[<c00d8308>] (tty_release+0x0/0x1c) from [<c0072d6c>] (__fput+0x58/0x13c)
[<c0072d14>] (__fput+0x0/0x13c) from [<c007175c>] (filp_close+0x84/0x90)
[<c00716d8>] (filp_close+0x0/0x90) from [<c0028a40>] (ret_fast_syscall+0x0/0x2c)ircomm_close()
Obviously, uniprocessor configuration, irda built completely modular.
Signature · 4 lines
Russell King
Linux kernel 2.6 ARM Linux - http://www.arm.linux.org.uk/
maintainer of: 2.6 PCMCIA - http://pcmcia.arm.linux.org.uk/
2.6 Serial coreQuoted 4 lines · On Fri, 26 Dec 2003 13:00:31 +0000 Russell King <[email protected]>…
I've just been testing
w83977af_irwith ircomm on a NetWinder (ARM) and a Nokia mobile phone, and, while closing down the connection by exiting minicom, I saw this which looks particularly evil. I'm not sure exactly when this occurred because I was running minicom over ssh.
This is akin to the PPP issues, and all of this basically is telling that the TTY driver's locking conflicts with networking quite badly.
In this case:
Quoted 3 lines
Badness in
local_bh_enableatkernel/softirq.c:121
[<c00429c4>] (local_bh_enable+0x0/0x84) from [<c014d1b4>] (dev_queue_xmit+0x108/0x20c) [<c014d0ac>] (dev_queue_xmit+0x0/0x20c) from [<bf00ee68>] (irlap_send_data_primary_poll+0xdc/0x1c4[irda])
local_bh_enable() with hardware interrupts disabled, which is racy and illegal. Who disabled CPU interrupts? Let's see:
Quoted 1 line
[<
bf03b4b0>] (ircomm_tty_shutdown+0x0/0x178[ircomm_tty]) from [<bf03a9c0>] (ircomm_tty_close+0x15c/0x240[ircomm_tty])
And this is where the spin_lock_irqsave() occurs, that leads to all of the trouble.
On Fri, 26 Dec 2003, Russell King wrote:
Hi Russell,
Quoted 9 lines
I've just been testing
w83977af_irwith ircomm on a NetWinder (ARM) and a Nokia mobile phone, and, while closing down the connection by exiting minicom, I saw this which looks particularly evil. I'm not sure exactly when this occurred because I was running minicom over ssh.Badness in
local_bh_enableatkernel/softirq.c:121
[<c00429c4>] (local_bh_enable+0x0/0x84) from [<c014d1b4>] (dev_queue_xmit+0x108/0x20c)
[<c014d0ac>] (dev_queue_xmit+0x0/0x20c) from [<bf00ee68>] (irlap_send_data_primary_poll+0xdc/0x1c4[irda]) [<bf00ed8c>] (irlap_send_data_primary_poll+0x0/0x1c4[irda]) from [<bf00babc>] (irlap_state_xmit_p+0x1a4/0x308[irda])
Yes, Thanks. It's a known problem with 2.6.0: sirdev_txlock-patch is waiting on Jean's page to get forwarded - for 2.6.[12] I assume.
Beware, there's another local_bh_enable issue with ircomm even with this patch applied. It's triggered when the ircomm-dev wasn't closed by the application before exiting (say kill -9 f.e.). So if you get another such badness warning with slightly different backtrace, chances are you also want to apply the "IrCOMM detach Oops" fixes from Jean's page.
Martin
-------------------
drivers/net/irda/sir_dev.c +13 -10
@@ -62,24 +62,25 @@ int sirdev_set_dongle(struct sir_dev *deint sirdev_raw_write (struct sir_dev *dev,const char *buf,int len) { +unsigned long flags;int ret;if (unlikely (len > dev->tx_buff.truesize))return -ENOSPC ; -spin_lock_bh (&dev->tx_lock);/* serialize with other tx operations */ -while (dev->tx_buff.len >0 ) {/* wait until tx idle */ -spin_unlock_bh (&dev->tx_lock); +spin_lock_irqsave (&dev->tx_lock, flags);/* serialize with other tx operations */ +while (dev->tx_buff.len >0 ) {/* wait until tx idle */ +spin_unlock_irqrestore (&dev->tx_lock, flags);set_current_state (TASK_UNINTERRUPTIBLE );schedule_timeout (MSECS_TO_JIFFIES (10 )); -spin_lock_bh (&dev->tx_lock); +spin_lock_irqsave (&dev->tx_lock, flags); } dev->tx_buff.data = dev->tx_buff.head;memcpy (dev->tx_buff.data, buf, len); ret = dev->drv->do_write (dev, dev->tx_buff.data, dev->tx_buff.len); -spin_unlock_bh (&dev->tx_lock); +spin_unlock_irqrestore (&dev->tx_lock, flags);return ret; }
@@ -114,11 +115,12 @@ int sirdev_raw_read(struct sir_dev *dev,void sirdev_write_complete (struct sir_dev *dev) { +unsigned long flags;struct sk_buff *skb;int actual =0 ;int err; -spin_lock_bh (&dev->tx_lock); +spin_lock_irqsave (&dev->tx_lock, flags);IRDA_DEBUG (3 ,"%s() - dev->tx_buff.len = %d\n" , __FUNCTION__, dev->tx_buff.len);
@@ -143,7 +145,7 @@ void sirdev_write_complete(struct sir_de dev->tx_buff.len =0 ; }if (dev->tx_buff.len >0 ) { -spin_unlock_bh (&dev->tx_lock); +spin_unlock_irqrestore (&dev->tx_lock, flags);return ; } }
@@ -190,7 +192,7 @@ void sirdev_write_complete(struct sir_denetif_wake_queue (dev->netdev); } -spin_unlock_bh (&dev->tx_lock); +spin_unlock_irqrestore (&dev->tx_lock, flags); }/* called from client driver - likely with bh-context - to give us
@@ -258,6 +260,7 @@ static struct net_device_stats *sirdev_gstatic int sirdev_hard_xmit (struct sk_buff *skb,struct net_device *ndev) {struct sir_dev *dev = ndev->priv; +unsigned long flags;int actual =0 ;int err;s32 speed;
@@ -307,7 +310,7 @@ static int sirdev_hard_xmit(struct sk_bu }/* serialize with write completion */ -spin_lock_bh (&dev->tx_lock); +spin_lock_irqsave (&dev->tx_lock, flags);/* Copy skb to tx_buff while wrapping, stuffing and making CRC */ dev->tx_buff.len =async_wrap_skb (skb, dev->tx_buff.data, dev->tx_buff.truesize);
@@ -337,7 +340,7 @@ static int sirdev_hard_xmit(struct sk_bu dev->stats.tx_dropped++;netif_wake_queue (ndev); } -spin_unlock_bh (&dev->tx_lock); +spin_unlock_irqrestore (&dev->tx_lock, flags);return 0 ; }
drivers/net/irda/sir_kthread.c +4 -5
@@ -436,14 +436,13 @@ int sirdev_schedule_request(struct sir_dIRDA_DEBUG (2 ,"%s - state=0x%04x / param=%u\n" , __FUNCTION__, initial_state, param); -if (in_interrupt ()) { -if (down_trylock (&fsm->sem)) { +if (down_trylock (&fsm->sem)) { +if (in_interrupt () ||in_atomic () ||irqs_disabled ()) {IRDA_DEBUG (1 ,"%s(), state machine busy!\n" , __FUNCTION__);return -EWOULDBLOCK ; - } + }else +down (&fsm->sem); } -else -down (&fsm->sem);if (fsm->state ==SIRDEV_STATE_DEAD ) {/* race with sirdev_close should never happen */
Quoted 5 lines · Martin Diehl
Beware, there's another
local_bh_enableissue with ircomm even with this patch applied. It's triggered when the ircomm-dev wasn't closed by the application before exiting (say kill -9 f.e.). So if you get another such badness warning with slightly different backtrace, chances are you also want to apply the "IrCOMM detach Oops" fixes from Jean's page.
Oops, right after sending this I realized you aren't using the sirdev at all, so in fact this is already the second case triggered from the ircomm-shutdown path - like davem was already pointing to. Below said patch from Jean.
Martin
----------------------------
include/net/irda/ircomm_tty.h renamed from include/net/irda/ircomm_tty.d4.h +6 -1
@@ -52,6 +52,11 @@/* Same for payload size. See qos.c for the smallest max data size */ #define IRCOMM_TTY_DATA_UNINITIALISED (64 - IRCOMM_TTY_HDR_UNINITIALISED) +/* Those are really defined in include/linux/serial.h - Jean II */ +#define ASYNC_B_INITIALIZED 31/* Serial port was initialized */ +#define ASYNC_B_NORMAL_ACTIVE 29/* Normal device is active */ +#define ASYNC_B_CLOSING 27/* Serial port is closing */ +/* * IrCOMM TTY driver state */
@@ -75,7 +80,7 @@ struct ircomm_tty_cb {LOCAL_FLOW flow;/* IrTTP flow status */ int line; -__u32 flags; +volatile unsigned long flags;__u8 dlsap_sel;__u8 slsap_sel;
net/irda/ircomm/ircomm_tty.c renamed from net/irda/ircomm/ircomm_tty.d4.c +21 -18
@@ -182,15 +182,15 @@ void __exit ircomm_tty_cleanup(void)static int ircomm_tty_startup (struct ircomm_tty_cb *self) {notify_t notify; -int ret; +int ret = -ENODEV ;IRDA_DEBUG (2 ,"%s()\n" , __FUNCTION__ ); ASSERT(self != NULL, return -1;); ASSERT(self->magic == IRCOMM_TTY_MAGIC, return -1;); -/* Already open */ -if (self->flags &ASYNC_INITIALIZED ) { +/* Check if already open */ +if (test_and_set_bit (ASYNC_B_INITIALIZED , &self->flags)) {IRDA_DEBUG (2 ,"%s(), already open so break out!\n" , __FUNCTION__ );return 0 ; }
@@ -214,7 +214,7 @@ static int ircomm_tty_startup(struct irc self->line); }if (!self->ircomm) -return -ENODEV ; + goto err; self->slsap_sel = self->ircomm->slsap_sel;
@@ -222,12 +222,13 @@ static int ircomm_tty_startup(struct irc ret =ircomm_tty_attach_cable (self);if (ret <0 ) {ERROR ("%s(), error attaching cable!\n" , __FUNCTION__); -return ret; + goto err; } - self->flags |=ASYNC_INITIALIZED ; -return 0 ; +err: +clear_bit (ASYNC_B_INITIALIZED , &self->flags); +return ret; }/*
@@ -300,7 +301,8 @@ static int ircomm_tty_block_til_ready(st current->state =TASK_INTERRUPTIBLE ; -if (tty_hung_up_p (filp) || !(self->flags &ASYNC_INITIALIZED )){ +if (tty_hung_up_p (filp) || + !test_bit (ASYNC_B_INITIALIZED , &self->flags)) { retval = (self->flags &ASYNC_HUP_NOTIFY ) ? -EAGAIN : -ERESTARTSYS ;break ;
@@ -311,7 +313,7 @@ static int ircomm_tty_block_til_ready(st* specified, we cannot return before the IrCOMM link is * ready */ -if (!(self->flags &ASYNC_CLOSING ) && +if (!test_bit (ASYNC_B_CLOSING , &self->flags) && (do_clocal || (self->settings.dce &IRCOMM_CD )) && self->state ==IRCOMM_TTY_READY ) {
@@ -426,7 +428,7 @@ static int ircomm_tty_open(struct tty_st* If the port is the middle of closing, bail out now */ if (tty_hung_up_p (filp) || - (self->flags &ASYNC_CLOSING )) { +test_bit (ASYNC_B_CLOSING , &self->flags)) {/* Hm, why are we blocking on ASYNC_CLOSING if we * do return -EAGAIN/-ERESTARTSYS below anyway?
@@ -436,7 +438,7 @@ static int ircomm_tty_open(struct tty_st* probably better sleep uninterruptible? */ -if (wait_event_interruptible (self->close_wait, !(self->flags&ASYNC_CLOSING ))) { +if (wait_event_interruptible (self->close_wait, !test_bit (ASYNC_B_CLOSING , &self->flags))) {WARNING ("%s - got signal while blocking on ASYNC_CLOSING!\n" , __FUNCTION__);return -ERESTARTSYS ;
@@ -531,11 +533,13 @@ static void ircomm_tty_close(struct tty_IRDA_DEBUG (0 ,"%s(), open count > 0\n" , __FUNCTION__ );return ; } - self->flags |=ASYNC_CLOSING ; + +/* Hum... Should be test_and_set_bit ??? - Jean II */ +set_bit (ASYNC_B_CLOSING , &self->flags);/* We need to unlock here (we were unlocking at the end of this * function), because tty_wait_until_sent() may schedule. -* I don't know if the rest should be locked somehow, +* I don't know if the rest should be protected somehow, * so someone should check. - Jean II */ spin_unlock_irqrestore (&self->spinlock, flags);
@@ -979,10 +983,12 @@ static void ircomm_tty_shutdown(struct i ASSERT(self->magic == IRCOMM_TTY_MAGIC, return;);IRDA_DEBUG (0 ,"%s()\n" , __FUNCTION__ ); - -if (!(self->flags &ASYNC_INITIALIZED )) + +if (!test_and_clear_bit (ASYNC_B_INITIALIZED , &self->flags))return ; +ircomm_tty_detach_cable (self); +spin_lock_irqsave (&self->spinlock, flags);del_timer (&self->watchdog_timer);
@@ -999,13 +1005,10 @@ static void ircomm_tty_shutdown(struct i self->tx_skb =NULL ; } -ircomm_tty_detach_cable (self); -if (self->ircomm) {ircomm_close (self->ircomm); self->ircomm =NULL ; } - self->flags &= ~ASYNC_INITIALIZED ;spin_unlock_irqrestore (&self->spinlock, flags); }
Quoted 8 lines · On Sat, 27 Dec 2003 00:33:34 +0100 (CET) Martin Diehl <[email protected]> wrote:
Quoted 5 lines · Martin Diehl
Beware, there's another
local_bh_enableissue with ircomm even with this patch applied. It's triggered when the ircomm-dev wasn't closed by the application before exiting (say kill -9 f.e.). So if you get another such badness warning with slightly different backtrace, chances are you also want to apply the "IrCOMM detach Oops" fixes from Jean's page.
Quoted 4 lines
Oops, right after sending this I realized you aren't using the sirdev at all, so in fact this is already the second case triggered from the ircomm-shutdown path - like davem was already pointing to. Below said patch from Jean.
I'm going to add this to my tree, the patch looks perfectly fine and we might as well get this thing fixed now rather than later.