(irda) Badness in local_bh_enable at kernel/softirq.c:121

(irda) Badness in local_bh_enable at kernel/softirq.c:121

[Russell King]

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=04
ircomm_param_service_type(), resulting service type=0x04
ircomm_param_port_type(), port type=1
ircomm_param_port_type(), port type=1
ircomm_param_xon_xoff(), XON/XOFF = 0x11,0x13
ircomm_param_enq_ack(), ENQ/ACK = 0x13,0x11
ircomm_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.

-- 
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 core

Re: (irda) Badness in local_bh_enable at kernel/softirq.c:121

[David S. Miller]

On Fri, 26 Dec 2003 13:00:31 +0000
Russell King <rmk+lkml@arm.linux.org.uk> wrote:

> 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.

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:

> 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])

local_bh_enable() with hardware interrupts disabled, which is
racy and illegal.  Who disabled CPU interrupts?  Let's see:

> [<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.

Re: [irda-users] (irda) Badness in local_bh_enable at kernel/softirq.c:121

[Martin Diehl]

On Fri, 26 Dec 2003, Russell King wrote:

Hi Russell,

> 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.
> 
> 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])

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

-------------------

--- linux-2.6.0-test9-bk22/drivers/net/irda/sir_dev.c	Wed Oct  8 21:24:16 2003
+++ v2.6.0-test9-bk22/drivers/net/irda/sir_dev.c	Tue Nov 18 00:01:38 2003
@@ -62,24 +62,25 @@ int sirdev_set_dongle(struct sir_dev *de
 
 int 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_de
 		netif_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_g
 static 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;
 }
--- linux-2.6.0-test9-bk22/drivers/net/irda/sir_kthread.c	Wed Oct  8 21:24:27 2003
+++ v2.6.0-test9-bk22/drivers/net/irda/sir_kthread.c	Mon Nov 17 17:39:54 2003
@@ -436,14 +436,13 @@ int sirdev_schedule_request(struct sir_d
 
 	IRDA_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 */

Re: [irda-users] (irda) Badness in local_bh_enable at kernel/softirq.c:121

[Martin Diehl]

On Sat, 27 Dec 2003, Martin Diehl wrote:

> 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.

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

----------------------------

diff -u -p linux/include/net/irda/ircomm_tty.d4.h linux/include/net/irda/ircomm_tty.h
--- linux/include/net/irda/ircomm_tty.d4.h	Thu Dec 18 18:22:57 2003
+++ linux/include/net/irda/ircomm_tty.h	Thu Dec 18 18:29:01 2003
@@ -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;
diff -u -p linux/net/irda/ircomm_tty.d4.c linux/net/irda/ircomm_tty.c
--- linux/net/irda/ircomm/ircomm_tty.d4.c	Thu Dec 18 17:40:14 2003
+++ linux/net/irda/ircomm/ircomm_tty.c	Thu Dec 18 18:29:09 2003
@@ -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);
 }

Re: [irda-users] (irda) Badness in local_bh_enable at kernel/softirq.c:121

[David S. Miller]

On Sat, 27 Dec 2003 00:33:34 +0100 (CET)
Martin Diehl <lists@mdiehl.de> wrote:

> On Sat, 27 Dec 2003, Martin Diehl wrote:
> 
> > 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.
> 
> 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.