Got this on a serial console today, using 2.6.25-rc2-git1. Machine was

not doing anything interesting at the time, but has its / and kernel on

a usb-storage device (usb pen drive).
Intel ICH8R chipset (and USB controller), running x86_64 kernel. I'll

post .config and some additional info when I get home later if it isn't

--

From: Andre Tomt <andre@tomt.net>
FWIW, I've seen a near identical crash on my Niagara system.
The only USB device attached is a CD/DVDW drive sitting behind

usb-storage.

--

Please try that diagnostic patch I sent ... with CONFIG_USB_DEBUG.
Near as I can tell this is caused by some hardware oddity that needs

to be worked around.  We seem to be at stage where we've fixed some

problems, nudging code paths around so another one shows up, and have

incidentally had a new silicion-specific hardware erratum reported

in this area.  So more info is needed...
A quick anti-oops patch is appended, it should work OK on top of that

diagnostic patch, but won't necessarily resolve the underlying problem.
- Dave
--- g26.orig/drivers/usb/host/ehci-q.c	2008-02-19 16:15:04.000000000 -0800

+++ g26/drivers/usb/host/ehci-q.c	2008-02-19 16:15:59.000000000 -0800

@@ -993,6 +993,11 @@ static void end_unlink_async (struct ehc
 	iaa_watchdog_done(ehci);
+	if (!qh) {

+		WARN_ON(1);

+		return;

+	}

+

 	// qh->hw_next = cpu_to_hc32(qh->qh_dma);

 	qh->qh_state = QH_STATE_IDLE;

 	qh->qh_next.qh = NULL;

--

It will be interesting to see the stack dump.  As far as I can tell,

there are two pathways which could lead qh being NULL.  One is the IAA

hardware peculiarity (setting the status bit very late, after the

watchdog timer has already expired), and the other is in unlink_async()

if the controller isn't running.  That second one may be just a simple

bug -- I doubt it would show up unless the controller got a fatal

error and stopped.
Alan Stern
--

From: David Brownell <david-b@pacbell.net>
I have that patch applied with USB_DEBUG enabled, I'll let you know

if it triggers.
It doesn't happen often, say once in every 20 or so boots.

--

Can you provide some sort of disassembly listing of end_unlink_async,

to determine which C statement contained the NULL pointer dereference?
Alan Stern
--

--

Can you try this diagnostic patch, to see if it reports any messages

about IAA and/or IAAD oddities?  There's surely a quick workaround

for this, but I'd rather understand the root cause before patching.
- Dave
Work around for an evident bug in one EHCI controller:  IAA didn't get

set when IAAD was cleared.  Evidently writing the status register can

prevent setting IAA; someone's VHDL (or whatever) code was wrong.

This workaround catches that specific bug (in the IRQ handler and in

the IAA watchdog) and treats it as if IAA was properly set.
The patch also adds *LOTS* of related paranoia, insisting IAAD is clear

(or set, as appropriate) at various points, and adding code to improve

the handling of some such cases.  It also raises the volume and precision

of debug messaging related to IAA problems.
This patch is EXPERIMENTAL and DIAGNOSTIC ... not intended for merge.

It's also in *addition* to the IAA watchdog timer rework that's already

been merged into 2.6.25-rc1, which will help some systems.
If you use this, run with CONFIG_USB_DEBUG enabled.  Most messages

with IAA or IAAD should then be "interesting" in the sense that they

will indicate something odd happening ... maybe something that's

fully worked around, maybe not.
---

 drivers/usb/host/ehci-hcd.c |   38 ++++++++++++++++++++++++++++++--------

 drivers/usb/host/ehci-q.c   |   27 ++++++++++++++++++++++++++-

 2 files changed, 56 insertions(+), 9 deletions(-)
--- g26.orig/drivers/usb/host/ehci-hcd.c	2008-02-11 19:18:39.000000000 -0800

+++ g26/drivers/usb/host/ehci-hcd.c	2008-02-13 15:30:56.000000000 -0800

@@ -255,21 +255,33 @@ static void ehci_iaa_watchdog(unsigned l

 	u32			status, cmd;
 	spin_lock_irqsave (&ehci->lock, flags);

-	WARN_ON(!ehci->reclaim);
 	status = ehci_readl(ehci, &ehci->regs->status);

 	cmd = ehci_readl(ehci, &ehci->regs->command);

-	ehci_dbg(ehci, "IAA watchdog: status %x cmd %x\n", status, cmd);
 	/* lost IAA irqs wedge things badly; seen first with ...
[ message continues ]

Doesn't seem to have triggered anything. dmesg attached in case I missed

anything.
Note that this does not happen at all with 2.6.24, but with

2.6.25-rc2-git1 it usually crashes at boot. If not, it crashes after

about an hour (pretty random, but it never lasts very long.)

You don't seem to have enabled CONFIG_USB_DEBUG, as the patch instructions

say is needed to get such diagnostics ... I can tell because the startup

messages from USB are pretty minimal.  (See appended, vs what you sent...)
Please try again with USB debugging enabled.
- Dave
ehci_hcd 0000:00:02.2: new USB bus registered, assigned bus number 3

ehci_hcd 0000:00:02.2: reset hcs_params 0x102486 dbg=1 cc=2 pcc=4 !ppc ports=6

ehci_hcd 0000:00:02.2: reset portroute 0 0 1 1 1 0

ehci_hcd 0000:00:02.2: reset hcc_params a086 caching frame 256/512/1024 park

ehci_hcd 0000:00:02.2: park 0

ehci_hcd 0000:00:02.2: reset command 080b02 park=3 ithresh=8 period=1024 Reset HALT

PCI: cache line size of 64 is not supported by device 0000:00:02.2

ehci_hcd 0000:00:02.2: supports USB remote wakeup

ehci_hcd 0000:00:02.2: irq 22, io mem 0xe8004000

ehci_hcd 0000:00:02.2: reset command 080b02 park=3 ithresh=8 period=1024 Reset HALT

ehci_hcd 0000:00:02.2: init command 010009 (park)=0 ithresh=1 period=256 RUN

ehci_hcd 0000:00:02.2: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004

...
--

Argh, silly me. Here you go (attached). It has not crashed yet with the

patch though.

... etc.
OK, the relevant bits are:
   status  0001 == some transaction completed normally (ignored here)

   status  0020 == IAA set, which should have triggered an IRQ

   command 0040 == IAAD clear, meaning IAA should have triggered
Meaning the hardware is misbehaving in a "traditional" way, one

that the watchdog is supposed to catch:  IAA set, but no IRQ.
If you see any "IAA" messages *other* than those, please report
It seems that one of the tweks in this patch made the watchdog

act better than before.  So unless I hear from you (before the

start of next week) that some other message appears, or that your

oops re-appears, I'll submit some version of this patch for RC3.
And if you're up for it, I may have another patch for you

to try on top of this one ... I had an idea about IRQ trigger

modes that might be causing this problem.
- Dave

--

OOPS'ed again after some hours. The OOPS looks identical to me besides

all kind of other crap mixed in the trace due to a lot of unrelated

activity going on.
Quite a lot of the same IAA messages (status 8029 and 8028, cmd 10021)

in /var/log/debug prior to the crash, over the entire uptime time span.
It'll have to be tomorrow. Should I throw in the anti-oops patch too?

--

Sure.  I expect you'll see the stacktrace then, instead of oopsing.
You might turn that one IAA message into an ehci_vdbg() call

instead of an ehci_dbg() call, since  the data it gives isn't

useful.  That would reduce the amount of log noise you seee.
- Dave
--

lines in the log brings up some ideas that have been percolating in my

mind for a while.  They have to do with the possibility of a race

between the watchdog routine and assertion of IAA.
In fact, if the timing comes out just wrong then it's possible (on SMP

systems) for an IAA interrupt to arrive when the watchdog

routine has already started running.  Then end_unlink_async() might get

called right at the start of a new IAA cycle, or when the reclaim list

is empty.
Alan Stern
--

The curious bit IMO being STS_INT (0001), which should also have

triggered an IRQ.  Suggesting to me that the race might be lower

level than that ... at the level of a conflict between the various

mechanisms to ack irqs.
See the appended patch (Andre, this is the additional one I meant)
The driver's spinlock should prevent that particular problem from

appearing.
- Dave
========= CUT HERE

Modify EHCI irq handling on the theory that at least some of the

"lost" IRQs are caused by goofage between multiple lowlevel IRQ

acking mechanisms:  try rescanning before we exit the handler, in

case the EHCI-internal ack (by clearing the irq status) doesn't

always suffice for IRQs triggered nearly back-to-back.
---

 drivers/usb/host/ehci-hcd.c |    8 ++++++++

 1 file changed, 8 insertions(+)
--- g26.orig/drivers/usb/host/ehci-hcd.c	2008-02-20 13:26:00.000000000 -0800

+++ g26/drivers/usb/host/ehci-hcd.c	2008-02-20 13:54:37.000000000 -0800

@@ -638,6 +638,8 @@ static irqreturn_t ehci_irq (struct usb_

 		return IRQ_NONE;

 	}
+retrigger:

+

 	/* clear (just) interrupts */

 	ehci_writel(ehci, status, &ehci->regs->status);

 	cmd = ehci_readl(ehci, &ehci->regs->command);

@@ -725,6 +727,12 @@ dead:
 	if (bh)

 		ehci_work (ehci);

+

+	status = ehci_readl(ehci, &ehci->regs->status);

+	status &= INTR_MASK;

+	if (status)

+		goto retrigger;

+

 	spin_unlock (&ehci->lock);

 	if (pcd_status & STS_PCD)

 		usb_hcd_poll_rh_status(hcd);

--

There's one little problem here.  As a result of this change, the line

where pcd_status gets set (not shown in this patch) needs to be changed

to:
		pcd_status |= (status & STS_PCD);
Then the test shown above can be simplified to:
	if (pcd_status)
Alan Stern
--

Actually, no change is needed.  It's initialized to zero, then

set to "status" given "if (status & STS_PCD)", and never cleared.
True with the current code too ...
--

Maybe it did trigger an IRQ.  Inside the watchdog routine interrupts 
I don't think so:
	CPU 0				CPU 1

	-----				-----

	Watchdog timer expires

	Timer routine acquires spinlock

					IAA IRQ arrives

					ehci_irq tries to acquire

						spinlock...

	Timer routine either sets

		ehci->reclaim to NULL

		or else starts a new

		IAA cycle

	Timer routine releases spinlock

		and returns

					ehci_irq acquires spinlock

						and sees IAA is set
This might help, but it won't fix the race outlined above.
Alan Stern
--

There's another condition here, and

another action.  The condition is

that ehci->reclaim must first be set;

the action is to clear STS_IAA (and,

given the previous patch, maybe IAAD).
And this "either" is more concisely

written as "call end_unlink_async()"
					Can only happen if a new IAA

					cycle was started by CPU0, and

					the IAA condition triggered

--

The following comment refers to the "Timer routine either sets" below, 
Correct on both counts.  I had forgotten that the watchdog routine 
Okay, so this isn't as bad as it seemed.  I don't have a copy of your

most recent patch, but it seems clear that the watchdog routine must:
	First remove the circumstances that would cause the controller

	to set IAA.  I guess that means clearing IAAD; it's not

	entirely clear from the spec whether this will do what we

	want.
	Then clear IAA (if it happens to be set).
This is the only way to avoid the race, and I know that my original

version of the routine does these steps in the wrong order (if at all).

That should be fixed.  Given sufficiently bizarre hardware we can't be

certain that things won't still go wrong on occasion, but this is the

best we can do for now -- weird hardware can be handled as it arises.
The other change to make (which you have already anticipated) is to

guard against ehci->reclaim == NULL in end_unlink_async().  There's no

real need for a warning or stack dump; it should just return silently

when this happens.  If there is a warning, maybe it should be placed at

the site of the caller (for example, in ehci_irq() when STS_IAA is

detected).
Alan Stern
--

The spec says that IAAD gets cleared when IAA is set.  Clearing

IAAD should strictly speaking never be needed if IAA is seen ...

but my latest patch will do so (on both watchdog and IRQ paths)
Yes; I re-ordered that to read IAAD first, to give more useful

diagnostics in case of an extremely belated trigger of IAA
The appended patch does include a bit of paranoia around IAA and IAAD;

I figure it can't hurt, although at this point I have no particular
Yeah, that seems like a better place to do it.  All the other callers

guarantee ehci->reclaim is non-null before calling it.  The fact that

it happens in this case suggests IAAD and/or IAAD didn't get cleared

properly.
- Dave
========== CUT HERE

The recent EHCI driver update to split the IAA watchdog timer out from

the other timers made several things work better, but not everything;

and it created a couple new issues in bugzilla.  Ergo this patch:
  - Handle a should-be-rare SMP race between the watchdog firing

    and (very late) IAA interrupts;
  - Remove a shouldn't-have-been-added WARN_ON() test;
  - Guard against one observed OOPS;
  - If this watchdog fires during clean HC shutdown, it should act

    as a NOP instead of interfering with the shutdown sequence;
  - Guard against silicon errata hypothesized by some vendors:

      * IAA status latch broken, but IAAD cleared OK;

      * IAAD wasn't cleared when IAA status got reported;
The WARN_ON is in bugzilla as 10168; the OOPS as 10078.
Signed-off-by: David Brownell <dbrownell@users.sourceforge.net>

---

 drivers/usb/host/ehci-hcd.c |   60 +++++++++++++++++++++++++++++++++-----------

 1 file changed, 45 insertions(+), 15 deletions(-)
--- g26.orig/drivers/usb/host/ehci-hcd.c	2008-03-04 17:24:22.000000000 -0800

+++ g26/drivers/usb/host/ehci-hcd.c	2008-03-04 20:08:28.000000000 -0800

@@ -257,23 +257,44 @@ static void ehci_iaa_watchdog(unsigned l

 {

 	struct ehci_hcd		*ehci = (struct ehci_hcd *) param;

 	unsigned long		flags;

-	u32			status, ...
[ message continues ]

It looks very good.  Do you think there should be an "else" clause for

the "if ((status & STS_IAA) || !(cmd & CMD_IAAD))" test?  That's the

pathway one would observe with a controller that implements IAA very

slowly or not at all.  There doesn't seem to be anything more the HCD 
There's still Bugzilla #8692.  That one appears to be an individual
There is one place where ehci-hcd.c doesn't make that guarantee:
@@ -757,7 +757,7 @@ static void unlink_async (struct ehci_hcd *eh

 static void unlink_async (struct ehci_hcd *ehci, struct ehci_qh *qh)

 {

 	/* failfast */

-	if (!HC_IS_RUNNING(ehci_to_hcd(ehci)->state))

+	if (!HC_IS_RUNNING(ehci_to_hcd(ehci)->state) && ehci->reclaim)

 		end_unlink_async(ehci);
 	/* if it's not linked then there's nothing to do */
But if you take out the WARN_ON at the start of end_unlink_async then

this isn't needed.
Alan Stern
--

Maybe; I noticed the "IAAD wasn't clear" message, but that should

actually have been tested earlier (before the completions fired).
Right, that's gone.
- Dave
--