Re: [REGRESSION] 2.6.24/25: random lockups when accessing external USB harddrive

[Stefan Becker <Stefan.Becker@nokia.com>]

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

Hi Alan,

ext Alan Stern wrote:
> 
> I don't know, but it's a good start.  The IRQs for uhci-hcd and
> ehci-hcd are registered using the IRQF_DISABLED flag, which means that
> the handler routines uhci_irq() and ehci_irq() should always be called
> with interrupts disabled.
> 
> So that's the next thing to test.  Put a raw_irqs_disabled() test at
> the start of those two routines, just to make sure that interrupts
> don't somehow get enabled by mistake while the routine is running.  If 
> interrupts are already enabled when the routines are called then the 
> bug is somewhere else in the kernel.

Second try, slightly different tack: no dump_stack() in the _irq() 
functions, but disabled/enabled indication. Plus debugging code added in 
usb_hcd_add() to see the interrupt registration. Again too much data was 
printed for the bug to appear.

Looking at the collected data it looks like

  - ehci_irq() is always entered with interrupts enabled (WRONG).

  - uhci_irq() is entered sometimes with either interrupts enabled 
(WRONG) or disabled (OK).

But both interrupts are registered with IRQF_DISABLED...

Regards,

	Stefan

---
Stefan Becker
E-Mail: Stefan.Becker@nokia.com

[-- Attachment #2: usb-dump-stack.patch --]
[-- Type: text/plain, Size: 3822 bytes --]

diff --git a/drivers/usb/core/hcd.c b/drivers/usb/core/hcd.c
index 09a53e7..1f065a9 100644
--- a/drivers/usb/core/hcd.c
+++ b/drivers/usb/core/hcd.c
@@ -1107,7 +1107,21 @@ EXPORT_SYMBOL_GPL(usb_hcd_check_unlink_urb);
 void usb_hcd_unlink_urb_from_ep(struct usb_hcd *hcd, struct urb *urb)
 {
 	/* clear all state linking urb to this dev (and hcd) */
+#ifdef DEBUG
+	if (!raw_irqs_disabled()) {
+		printk(KERN_CRIT "USB_HCD_UNLINK_URB_FROM_EP interrupts enabled!\n");
+		dump_stack();
+	}
+	if (!spin_trylock(&hcd_urb_list_lock)) {
+		int i;
+		printk(KERN_CRIT "HCD URB list locked!\n");
+		dump_stack();
+		for (i = 0; i < 100; i++) schedule();
+		panic("USB BUG TRIGGERED!\n");
+        }
+#else
 	spin_lock(&hcd_urb_list_lock);
+#endif
 	list_del_init(&urb->urb_list);
 	spin_unlock(&hcd_urb_list_lock);
 }
@@ -1862,6 +1876,12 @@ int usb_add_hcd(struct usb_hcd *hcd,
 	if (hcd->driver->irq) {
 		snprintf(hcd->irq_descr, sizeof(hcd->irq_descr), "%s:usb%d",
 				hcd->driver->description, hcd->self.busnum);
+#ifdef DEBUG
+		printk(KERN_CRIT "USB_ADD_HCD IRQ %s interrupts %s (0x%08lx)\n",
+		       hcd->irq_descr,
+		       (irqflags & IRQF_DISABLED) ? "disabled" : "enabled",
+		       irqflags);
+#endif
 		if ((retval = request_irq(irqnum, &usb_hcd_irq, irqflags,
 				hcd->irq_descr, hcd)) != 0) {
 			dev_err(hcd->self.controller,
diff --git a/drivers/usb/host/ehci-hcd.c b/drivers/usb/host/ehci-hcd.c
index 369a8a5..6f784e7 100644
--- a/drivers/usb/host/ehci-hcd.c
+++ b/drivers/usb/host/ehci-hcd.c
@@ -640,6 +640,17 @@ static irqreturn_t ehci_irq (struct usb_hcd *hcd)
 	u32			status, pcd_status = 0, cmd;
 	int			bh;
 
+#ifdef DEBUG
+	if (!raw_irqs_disabled()) {
+		printk(KERN_CRIT "EHCI_IRQ interrupts enabled!\n");
+#if 0
+		dump_stack();
+#endif
+        } else {
+		printk(KERN_CRIT "EHCI_IRQ interrupts disabled!\n");
+	}
+#endif
+
 	spin_lock (&ehci->lock);
 
 	status = ehci_readl(ehci, &ehci->regs->status);
diff --git a/drivers/usb/host/ehci-q.c b/drivers/usb/host/ehci-q.c
index b85b541..be0fa50 100644
--- a/drivers/usb/host/ehci-q.c
+++ b/drivers/usb/host/ehci-q.c
@@ -227,6 +227,15 @@ ehci_urb_done(struct ehci_hcd *ehci, struct urb *urb, int status)
 __releases(ehci->lock)
 __acquires(ehci->lock)
 {
+#ifdef DEBUG
+	if (!raw_irqs_disabled()) {
+		printk(KERN_CRIT "EHCI_URB_DONE interrupts enabled!\n");
+		dump_stack();
+        } else {
+		printk(KERN_CRIT "EHCI_URB_DONE interrupts disabled!\n");
+	}	  
+#endif
+
 	if (likely (urb->hcpriv != NULL)) {
 		struct ehci_qh	*qh = (struct ehci_qh *) urb->hcpriv;
 
diff --git a/drivers/usb/host/uhci-hcd.c b/drivers/usb/host/uhci-hcd.c
index 3a7bfe7..c01a93a 100644
--- a/drivers/usb/host/uhci-hcd.c
+++ b/drivers/usb/host/uhci-hcd.c
@@ -422,6 +422,17 @@ static irqreturn_t uhci_irq(struct usb_hcd *hcd)
 		return IRQ_NONE;
 	outw(status, uhci->io_addr + USBSTS);		/* Clear it */
 
+#ifdef DEBUG
+	if (!raw_irqs_disabled()) {
+		printk(KERN_CRIT "UHCI_IRQ interrupts enabled!\n");
+#if 0
+		dump_stack();
+#endif
+        } else {
+		printk(KERN_CRIT "UHCI_IRQ interrupts disabled!\n");
+	}
+#endif
+
 	if (status & ~(USBSTS_USBINT | USBSTS_ERROR | USBSTS_RD)) {
 		if (status & USBSTS_HSE)
 			dev_err(uhci_dev(uhci), "host system error, "
diff --git a/drivers/usb/host/uhci-q.c b/drivers/usb/host/uhci-q.c
index db64593..320e384 100644
--- a/drivers/usb/host/uhci-q.c
+++ b/drivers/usb/host/uhci-q.c
@@ -1495,6 +1495,15 @@ __acquires(uhci->lock)
 {
 	struct urb_priv *urbp = (struct urb_priv *) urb->hcpriv;
 
+#ifdef DEBUG
+	if (!raw_irqs_disabled()) {
+		printk(KERN_CRIT "UHCI_GIVEBACK_URB interrupts enabled!\n");
+		dump_stack();
+        } else {
+		printk(KERN_CRIT "UHCI_GIVEBACK_URB interrupts disabled!\n");
+	}
+#endif
+
 	if (qh->type == USB_ENDPOINT_XFER_CONTROL) {
 
 		/* urb->actual_length < 0 means the setup transaction didn't

[-- Attachment #3: dump_stack.txt.bz2 --]
[-- Type: application/x-bzip, Size: 40332 bytes --]