2.6.36-rc7: NULL pointer dereference in ehci_clear_tt_buffer_complete

2.6.36-rc7: NULL pointer dereference in ehci_clear_tt_buffer_complete

[Stefan Richter]

Hi,

I have got a monitor with built-in hub to which a keyboard, mouse, and
card reader are connected.  At one occasion when I switched the monitor
off, the following oops happened.

I have updated from 2.6.36-rc4 to 2.6.36-rc7 on Saturday evening.  I.e.
it may be a regression after 2.6.36-rc4, but isn't necessarily so.

Oct 11 22:16:30 stein -- MARK --
Oct 11 22:29:21 stein kernel: usb 1-1.2: USB disconnect, address 14
Oct 11 22:29:21 stein kernel: drivers/hid/usbhid/hid-core.c: can't reset device, 0000:00:12.2-1.3/input0, status -71
Oct 11 22:29:21 stein kernel: usb 1-1: clear tt 3 (00f0) error -71
Oct 11 22:29:21 stein kernel: drivers/hid/usbhid/hid-core.c: can't reset device, 0000:00:12.2-1.3/input1, status -71
Oct 11 22:29:21 stein kernel: hub 1-1:1.0: hub_port_status failed (err = -71)
Oct 11 22:29:21 stein kernel: hub 1-1:1.0: connect-debounce failed, port 2 disabled
Oct 11 22:29:21 stein kernel: usb 1-1: USB disconnect, address 12
Oct 11 22:29:21 stein kernel: usb 1-1.1: USB disconnect, address 13
Oct 11 22:29:21 stein kernel: usb 1-1.1.1: USB disconnect, address 16
Oct 11 22:29:21 stein kernel: usb 1-1: clear tt 3 (00f0) error -71
Oct 11 22:29:21 stein kernel: usb 1-1.3: USB disconnect, address 15
Oct 11 22:29:21 stein kernel: ehci_hcd 0000:00:12.2: qh ffff880208f07af0 (#00) state 5
Oct 11 22:29:21 stein kernel: drivers/hid/usbhid/hid-core.c: can't reset device, 0000:00:12.2-1.3/input0, status -108
Oct 11 22:29:21 stein kernel: usb 1-1: clear tt 3 (00f0) error -19
Oct 11 22:29:21 stein kernel: BUG: unable to handle kernel NULL pointer dereference at 0000000000000060
Oct 11 22:29:21 stein kernel: IP: [<ffffffff8129dbd8>] ehci_clear_tt_buffer_complete+0x31/0x72
Oct 11 22:29:21 stein kernel: PGD 16b51f067 PUD 16b520067 PMD 0 
Oct 11 22:29:21 stein kernel: Oops: 0002 [#1] PREEMPT SMP DEBUG_PAGEALLOC
Oct 11 22:29:21 stein kernel: last sysfs file: /sys/devices/pci0000:00/0000:00:02.0/0000:02:00.0/0000:03:02.0/0000:05:00.0/fw3/fw3.0/model_name
Oct 11 22:29:21 stein kernel: CPU 3 
Oct 11 22:29:21 stein kernel: Modules linked in: firedtv dvb_core ieee1394 firewire_ohci firewire_core crc_itu_t usb_storage cpufreq_ondemand powernow_k8 freq_table mperf nfsd lockd sunrpc exportfs snd_pcm_oss snd_mixer_oss snd_seq_oss snd_seq_midi_event snd_seq snd_seq_device ext4 jbd2 crc16 sr_mod yenta_socket snd_hda_codec_atihdmi cdrom snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_pcm pcmcia_core k10temp pcmcia_rsrc snd_timer pata_atiixp snd sg snd_page_alloc r8169 mii thermal processor
Oct 11 22:29:21 stein kernel: 
Oct 11 22:29:21 stein kernel: Pid: 25071, comm: kworker/3:3 Not tainted 2.6.36-rc7 #8 M3A78-EM/System Product Name
Oct 11 22:29:21 stein kernel: RIP: 0010:[<ffffffff8129dbd8>]  [<ffffffff8129dbd8>] ehci_clear_tt_buffer_complete+0x31/0x72
Oct 11 22:29:21 stein kernel: RSP: 0018:ffff880208f13d10  EFLAGS: 00010002
Oct 11 22:29:21 stein kernel: RAX: 0000000000000282 RBX: 0000000000000000 RCX: ffff8801f3539e80
Oct 11 22:29:21 stein kernel: RDX: 0000000000003101 RSI: ffffffff81ca6de0 RDI: ffff88021fc67608
Oct 11 22:29:21 stein kernel: RBP: ffff880208f13d40 R08: ffffffff81ca6de0 R09: 0000000000000000
Oct 11 22:29:21 stein kernel: R10: ffffffff8129dbd5 R11: ffffffff8129379d R12: ffff88021fc673f0
Oct 11 22:29:21 stein kernel: R13: ffff88021fc67608 R14: 0000000000000282 R15: ffff88021fc675e8
Oct 11 22:29:21 stein kernel: FS:  00007f2b5188c700(0000) GS:ffff880002b80000(0000) knlGS:00000000f6ac7700
Oct 11 22:29:21 stein kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
Oct 11 22:29:21 stein kernel: CR2: 0000000000000060 CR3: 000000016b51e000 CR4: 00000000000006e0
Oct 11 22:29:21 stein kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Oct 11 22:29:21 stein kernel: DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Oct 11 22:29:21 stein kernel: Process kworker/3:3 (pid: 25071, threadinfo ffff880208f12000, task ffff8801f3539e80)
Oct 11 22:29:21 stein kernel: Stack:
Oct 11 22:29:21 stein kernel: 0000000008f13d20 ffff88020ad4ca18 0000000000000282 ffff88020e2bca88
Oct 11 22:29:21 stein kernel: <0> ffff88020e2d37a8 ffff88020e2d38a0 ffff880208f13da0 ffffffff8128cc12
Oct 11 22:29:21 stein kernel: <0> 0000000000000000 0000000000000000 ffff8802000003e8 ffff88020e2d38d0
Oct 11 22:29:21 stein kernel: Call Trace:
Oct 11 22:29:21 stein kernel: [<ffffffff8128cc12>] hub_tt_work+0xd9/0x11c
Oct 11 22:29:21 stein kernel: [<ffffffff81045efa>] process_one_work+0x258/0x402
Oct 11 22:29:21 stein kernel: [<ffffffff81045e98>] ? process_one_work+0x1f6/0x402
Oct 11 22:29:21 stein kernel: [<ffffffff810476f0>] ? worker_thread+0x0/0x311
Oct 11 22:29:21 stein kernel: [<ffffffff8128cb39>] ? hub_tt_work+0x0/0x11c
Oct 11 22:29:21 stein kernel: [<ffffffff810476f0>] ? worker_thread+0x0/0x311
Oct 11 22:29:21 stein kernel: [<ffffffff810478cb>] worker_thread+0x1db/0x311
Oct 11 22:29:21 stein kernel: [<ffffffff810476f0>] ? worker_thread+0x0/0x311
Oct 11 22:29:21 stein kernel: [<ffffffff8104b54c>] kthread+0x81/0x89
Oct 11 22:29:21 stein kernel: [<ffffffff81002dd4>] kernel_thread_helper+0x4/0x10
Oct 11 22:29:21 stein kernel: [<ffffffff8102db9f>] ? finish_task_switch+0x69/0xa9
Oct 11 22:29:21 stein kernel: [<ffffffff81341000>] ? restore_args+0x0/0x30
Oct 11 22:29:21 stein kernel: [<ffffffff8104b4cb>] ? kthread+0x0/0x89
Oct 11 22:29:21 stein kernel: [<ffffffff81002dd0>] ? kernel_thread_helper+0x0/0x10
Oct 11 22:29:21 stein kernel: Code: 4c 8d bf f8 01 00 00 41 56 41 55 4c 8d af 18 02 00 00 41 54 49 89 fc 4c 89 ef 53 48 83 ec 08 48 8b 5e 20 e8 2f 28 0a 00 49 89 c6 <80> 63 60 fe 80 7b 49 03 75 20 48 8d 43 18 48 39 43 18 74 16 41 
Oct 11 22:29:21 stein kernel: RIP  [<ffffffff8129dbd8>] ehci_clear_tt_buffer_complete+0x31/0x72
Oct 11 22:29:21 stein kernel: RSP <ffff880208f13d10>
Oct 11 22:29:21 stein kernel: CR2: 0000000000000060
Oct 11 22:29:21 stein kernel: ---[ end trace 3730347d8bf09403 ]---
Oct 11 22:29:21 stein kernel: note: kworker/3:3[25071] exited with preempt_count 1
Oct 11 22:35:03 stein syslog-ng[3980]: syslog-ng starting up; version='3.1.2'

-- 
Stefan Richter
-=====-==-=- =-=- -=-==
http://arcgraph.de/sr/

Re: 2.6.36-rc7: NULL pointer dereference in ehci_clear_tt_buffer_complete

[Alan Stern]

On Mon, 11 Oct 2010, Stefan Richter wrote:

> Hi,
> 
> I have got a monitor with built-in hub to which a keyboard, mouse, and
> card reader are connected.  At one occasion when I switched the monitor
> off, the following oops happened.
> 
> I have updated from 2.6.36-rc4 to 2.6.36-rc7 on Saturday evening.  I.e.
> it may be a regression after 2.6.36-rc4, but isn't necessarily so.

I don't think it's a regression.

> Oct 11 22:29:21 stein kernel: usb 1-1.2: USB disconnect, address 14
> Oct 11 22:29:21 stein kernel: drivers/hid/usbhid/hid-core.c: can't reset device, 0000:00:12.2-1.3/input0, status -71
> Oct 11 22:29:21 stein kernel: usb 1-1: clear tt 3 (00f0) error -71
> Oct 11 22:29:21 stein kernel: drivers/hid/usbhid/hid-core.c: can't reset device, 0000:00:12.2-1.3/input1, status -71
> Oct 11 22:29:21 stein kernel: hub 1-1:1.0: hub_port_status failed (err = -71)
> Oct 11 22:29:21 stein kernel: hub 1-1:1.0: connect-debounce failed, port 2 disabled
> Oct 11 22:29:21 stein kernel: usb 1-1: USB disconnect, address 12
> Oct 11 22:29:21 stein kernel: usb 1-1.1: USB disconnect, address 13
> Oct 11 22:29:21 stein kernel: usb 1-1.1.1: USB disconnect, address 16
> Oct 11 22:29:21 stein kernel: usb 1-1: clear tt 3 (00f0) error -71
> Oct 11 22:29:21 stein kernel: usb 1-1.3: USB disconnect, address 15
> Oct 11 22:29:21 stein kernel: ehci_hcd 0000:00:12.2: qh ffff880208f07af0 (#00) state 5
> Oct 11 22:29:21 stein kernel: drivers/hid/usbhid/hid-core.c: can't reset device, 0000:00:12.2-1.3/input0, status -108
> Oct 11 22:29:21 stein kernel: usb 1-1: clear tt 3 (00f0) error -19
> Oct 11 22:29:21 stein kernel: BUG: unable to handle kernel NULL pointer dereference at 0000000000000060
> Oct 11 22:29:21 stein kernel: IP: [<ffffffff8129dbd8>] ehci_clear_tt_buffer_complete+0x31/0x72

Is this reproducible?  I'd guess that it happens only a fraction of the
times you turn off the monitor.  Maybe it will be more likely to happen 
if you are moving the mouse while you turn off the monitor.

At any rate, I'm baffled.  This log entry:

	ehci_hcd 0000:00:12.2: qh ffff880208f07af0 (#00) state 5

indicates that the ehci-hcd data structures were seriously messed up.  
It means the qh was not on the async list at a time when it should have
been (an URB for that qh was completing).

That led to ehci_clear_tt_buffer_complete crashing with qh == NULL,
which is what that IP address means, right?  You could add a test for
NULL, but that would merely cover up the symptom: qh should never be
NULL at that point.

Alan Stern

Re: 2.6.36-rc7: NULL pointer dereference in ehci_clear_tt_buffer_complete

[Alan Stern]

On Tue, 12 Oct 2010, Alan Stern wrote:

> On Mon, 11 Oct 2010, Stefan Richter wrote:
> 
> > Hi,
> > 
> > I have got a monitor with built-in hub to which a keyboard, mouse, and
> > card reader are connected.  At one occasion when I switched the monitor
> > off, the following oops happened.
> > 
> > I have updated from 2.6.36-rc4 to 2.6.36-rc7 on Saturday evening.  I.e.
> > it may be a regression after 2.6.36-rc4, but isn't necessarily so.
> 
> I don't think it's a regression.
> 
> > Oct 11 22:29:21 stein kernel: usb 1-1.2: USB disconnect, address 14
> > Oct 11 22:29:21 stein kernel: drivers/hid/usbhid/hid-core.c: can't reset device, 0000:00:12.2-1.3/input0, status -71
> > Oct 11 22:29:21 stein kernel: usb 1-1: clear tt 3 (00f0) error -71
> > Oct 11 22:29:21 stein kernel: drivers/hid/usbhid/hid-core.c: can't reset device, 0000:00:12.2-1.3/input1, status -71
> > Oct 11 22:29:21 stein kernel: hub 1-1:1.0: hub_port_status failed (err = -71)
> > Oct 11 22:29:21 stein kernel: hub 1-1:1.0: connect-debounce failed, port 2 disabled
> > Oct 11 22:29:21 stein kernel: usb 1-1: USB disconnect, address 12
> > Oct 11 22:29:21 stein kernel: usb 1-1.1: USB disconnect, address 13
> > Oct 11 22:29:21 stein kernel: usb 1-1.1.1: USB disconnect, address 16
> > Oct 11 22:29:21 stein kernel: usb 1-1: clear tt 3 (00f0) error -71
> > Oct 11 22:29:21 stein kernel: usb 1-1.3: USB disconnect, address 15
> > Oct 11 22:29:21 stein kernel: ehci_hcd 0000:00:12.2: qh ffff880208f07af0 (#00) state 5
> > Oct 11 22:29:21 stein kernel: drivers/hid/usbhid/hid-core.c: can't reset device, 0000:00:12.2-1.3/input0, status -108
> > Oct 11 22:29:21 stein kernel: usb 1-1: clear tt 3 (00f0) error -19
> > Oct 11 22:29:21 stein kernel: BUG: unable to handle kernel NULL pointer dereference at 0000000000000060
> > Oct 11 22:29:21 stein kernel: IP: [<ffffffff8129dbd8>] ehci_clear_tt_buffer_complete+0x31/0x72
> 
> Is this reproducible?  I'd guess that it happens only a fraction of the
> times you turn off the monitor.  Maybe it will be more likely to happen 
> if you are moving the mouse while you turn off the monitor.
> 
> At any rate, I'm baffled.  This log entry:
> 
> 	ehci_hcd 0000:00:12.2: qh ffff880208f07af0 (#00) state 5
> 
> indicates that the ehci-hcd data structures were seriously messed up.  
> It means the qh was not on the async list at a time when it should have
> been (an URB for that qh was completing).

Okay, I figured it out.  The trick is that a qh won't be on the async
list while one of its URBs is completing _if_ the URB was unlinked.  
Disabling the endpoint at that time triggers some bad logic, causing
the driver to think something is wrong even though it isn't.  Given
this insight, the patch below should fix the problem.

Stefan, is it possible for you to tell whether this really does work?
Dave, does this look right to you?

Alan Stern



Index: usb-2.6/drivers/usb/host/ehci-hcd.c
===================================================================
--- usb-2.6.orig/drivers/usb/host/ehci-hcd.c
+++ usb-2.6/drivers/usb/host/ehci-hcd.c
@@ -1063,10 +1063,11 @@ rescan:
 				tmp && tmp != qh;
 				tmp = tmp->qh_next.qh)
 			continue;
-		/* periodic qh self-unlinks on empty */
-		if (!tmp)
-			goto nogood;
-		unlink_async (ehci, qh);
+		/* periodic qh self-unlinks on empty, and a COMPLETING qh
+		 * may already be unlinked.
+		 */
+		if (tmp)
+			unlink_async(ehci, qh);
 		/* FALL THROUGH */
 	case QH_STATE_UNLINK:		/* wait for hw to finish? */
 	case QH_STATE_UNLINK_WAIT:
@@ -1083,7 +1084,6 @@ idle_timeout:
 		}
 		/* else FALL THROUGH */
 	default:
-nogood:
 		/* caller was supposed to have unlinked any requests;
 		 * that's not our job.  just leak this memory.
 		 */

Re: 2.6.36-rc7: NULL pointer dereference in ehci_clear_tt_buffer_complete

[Stefan Richter]

Alan Stern wrote:
> Stefan, is it possible for you to tell whether this really does work?

That will be hard.  So far I was unable to reproduce the oops; still running
unmodified 2.6.36-rc7.
-- 
Stefan Richter
-=====-==-=- =-=- -===-
http://arcgraph.de/sr/

Re: 2.6.36-rc7: NULL pointer dereference in ehci_clear_tt_buffer_complete

[Alan Stern]

On Thu, 14 Oct 2010, Stefan Richter wrote:

> Alan Stern wrote:
> > Stefan, is it possible for you to tell whether this really does work?
> 
> That will be hard.  So far I was unable to reproduce the oops; still running
> unmodified 2.6.36-rc7.

Was this on an SMP machine?  If yes, the untested patch below may help
trigger the oops.  To use it, insert (but don't mount) a memory card
into the card reader, and use dd to copy a large amount of data from
the card to /dev/null.  While that's running, unplug either the monitor
or the card reader.  You may want to do this at a VT console so you can
see directly when the delay occurs.

Alan Stern



Index: usb-2.6/drivers/usb/core/message.c
===================================================================
--- usb-2.6.orig/drivers/usb/core/message.c
+++ usb-2.6/drivers/usb/core/message.c
@@ -323,8 +323,13 @@ static void sg_complete(struct urb *urb)
 	/* on the last completion, signal usb_sg_wait() */
 	io->bytes += urb->actual_length;
 	io->count--;
-	if (!io->count)
+	if (!io->count) {
+		if (status == -ECONNRESET) {
+			printk(KERN_ERR "Delaying for test\n");
+			mdelay(600);
+		}
 		complete(&io->complete);
+	}
 
 	spin_unlock(&io->lock);
 }

Re: 2.6.36-rc7: NULL pointer dereference in ehci_clear_tt_buffer_complete

[Stefan Richter]

Alan Stern wrote:
> On Thu, 14 Oct 2010, Stefan Richter wrote:
> 
>> Alan Stern wrote:
>>> Stefan, is it possible for you to tell whether this really does work?
>> That will be hard.  So far I was unable to reproduce the oops; still running
>> unmodified 2.6.36-rc7.
> 
> Was this on an SMP machine?

Yes.

> If yes, the untested patch below may help
> trigger the oops.  To use it, insert (but don't mount) a memory card
> into the card reader, and use dd to copy a large amount of data from
> the card to /dev/null.  While that's running, unplug either the monitor
> or the card reader.  You may want to do this at a VT console so you can
> see directly when the delay occurs.
> 
> Alan Stern
> 
> 
> 
> Index: usb-2.6/drivers/usb/core/message.c
> ===================================================================
> --- usb-2.6.orig/drivers/usb/core/message.c
> +++ usb-2.6/drivers/usb/core/message.c
> @@ -323,8 +323,13 @@ static void sg_complete(struct urb *urb)
>  	/* on the last completion, signal usb_sg_wait() */
>  	io->bytes += urb->actual_length;
>  	io->count--;
> -	if (!io->count)
> +	if (!io->count) {
> +		if (status == -ECONNRESET) {
> +			printk(KERN_ERR "Delaying for test\n");
> +			mdelay(600);
> +		}
>  		complete(&io->complete);
> +	}
>  
>  	spin_unlock(&io->lock);
>  }
> 

I did so today on 2.6.36-rc8, without your other patch.  I was still unable to
reproduce the bug.  Forget the whole thing as unreproducible?
-- 
Stefan Richter
-=====-==-=- =-=- =----
http://arcgraph.de/sr/

Re: 2.6.36-rc7: NULL pointer dereference in ehci_clear_tt_buffer_complete

[Alan Stern]

On Sat, 16 Oct 2010, Stefan Richter wrote:

> Alan Stern wrote:
> > On Thu, 14 Oct 2010, Stefan Richter wrote:
> > 
> >> Alan Stern wrote:
> >>> Stefan, is it possible for you to tell whether this really does work?
> >> That will be hard.  So far I was unable to reproduce the oops; still running
> >> unmodified 2.6.36-rc7.
> > 
> > Was this on an SMP machine?
> 
> Yes.
> 
> > If yes, the untested patch below may help
> > trigger the oops.  To use it, insert (but don't mount) a memory card
> > into the card reader, and use dd to copy a large amount of data from
> > the card to /dev/null.  While that's running, unplug either the monitor
> > or the card reader.  You may want to do this at a VT console so you can
> > see directly when the delay occurs.
> > 
> > Alan Stern
> > 
> > 
> > 
> > Index: usb-2.6/drivers/usb/core/message.c
> > ===================================================================
> > --- usb-2.6.orig/drivers/usb/core/message.c
> > +++ usb-2.6/drivers/usb/core/message.c
> > @@ -323,8 +323,13 @@ static void sg_complete(struct urb *urb)
> >  	/* on the last completion, signal usb_sg_wait() */
> >  	io->bytes += urb->actual_length;
> >  	io->count--;
> > -	if (!io->count)
> > +	if (!io->count) {
> > +		if (status == -ECONNRESET) {
> > +			printk(KERN_ERR "Delaying for test\n");
> > +			mdelay(600);
> > +		}
> >  		complete(&io->complete);
> > +	}
> >  
> >  	spin_unlock(&io->lock);
> >  }
> > 
> 
> I did so today on 2.6.36-rc8, without your other patch.  I was still unable to
> reproduce the bug.  Forget the whole thing as unreproducible?

What I said above wasn't quite right.  This won't help trigger the 
oops, but it should trigger the line saying something like

	ehci_hcd 0000:00:12.2: qh ffff880208f07af0 (#00) state 5

That's the real bug.

Alan Stern

Re: 2.6.36-rc7: NULL pointer dereference in ehci_clear_tt_buffer_complete

[Stefan Richter]

Alan Stern wrote:
> On Sat, 16 Oct 2010, Stefan Richter wrote:
>> Alan Stern wrote:
>>> --- usb-2.6.orig/drivers/usb/core/message.c
>>> +++ usb-2.6/drivers/usb/core/message.c
>>> @@ -323,8 +323,13 @@ static void sg_complete(struct urb *urb)
>>>  	/* on the last completion, signal usb_sg_wait() */
>>>  	io->bytes += urb->actual_length;
>>>  	io->count--;
>>> -	if (!io->count)
>>> +	if (!io->count) {
>>> +		if (status == -ECONNRESET) {
>>> +			printk(KERN_ERR "Delaying for test\n");
>>> +			mdelay(600);
>>> +		}
>>>  		complete(&io->complete);
>>> +	}
>>>  
>>>  	spin_unlock(&io->lock);
>>>  }
>>>
>> I did so today on 2.6.36-rc8, without your other patch.  I was still unable to
>> reproduce the bug.  Forget the whole thing as unreproducible?
> 
> What I said above wasn't quite right.  This won't help trigger the 
> oops, but it should trigger the line saying something like
> 
> 	ehci_hcd 0000:00:12.2: qh ffff880208f07af0 (#00) state 5
> 
> That's the real bug.

# grep ' qh ' /var/log/messages
Oct 11 22:29:21 stein kernel: ehci_hcd 0000:00:12.2: qh ffff880208f07af0 (#00)
state 5

I.e. there was none anymore since the one which I reported on Monday.
-- 
Stefan Richter
-=====-==-=- =-=- =----
http://arcgraph.de/sr/

Re: 2.6.36-rc7: NULL pointer dereference in ehci_clear_tt_buffer_complete

[Alan Stern]

On Sat, 16 Oct 2010, Stefan Richter wrote:

> > What I said above wasn't quite right.  This won't help trigger the 
> > oops, but it should trigger the line saying something like
> > 
> > 	ehci_hcd 0000:00:12.2: qh ffff880208f07af0 (#00) state 5
> > 
> > That's the real bug.
> 
> # grep ' qh ' /var/log/messages
> Oct 11 22:29:21 stein kernel: ehci_hcd 0000:00:12.2: qh ffff880208f07af0 (#00)
> state 5
> 
> I.e. there was none anymore since the one which I reported on Monday.

Evidently this bug is pretty difficult to get hold of.  There has to be 
an URB that is unlinked at the time the endpoint gets disabled, and 
ideally it should have failed with a communications error (because the 
device was unplugged).  Going to the trouble to arrange all that 
doesn't seem worthwhile.

On the whole we shouldn't need to worry about it -- except that I think
the patch itself is worthwhile, pending review by David.

Alan Stern

Re: 2.6.36-rc7: NULL pointer dereference in ehci_clear_tt_buffer_complete

[Alan Stern]

On Sun, 17 Oct 2010, Alan Stern wrote:

> On Sat, 16 Oct 2010, Stefan Richter wrote:
> 
> > > What I said above wasn't quite right.  This won't help trigger the 
> > > oops, but it should trigger the line saying something like
> > > 
> > > 	ehci_hcd 0000:00:12.2: qh ffff880208f07af0 (#00) state 5
> > > 
> > > That's the real bug.
> > 
> > # grep ' qh ' /var/log/messages
> > Oct 11 22:29:21 stein kernel: ehci_hcd 0000:00:12.2: qh ffff880208f07af0 (#00)
> > state 5
> > 
> > I.e. there was none anymore since the one which I reported on Monday.
> 
> Evidently this bug is pretty difficult to get hold of.  There has to be 
> an URB that is unlinked at the time the endpoint gets disabled, and 
> ideally it should have failed with a communications error (because the 
> device was unplugged).  Going to the trouble to arrange all that 
> doesn't seem worthwhile.

Okay, here's a patch which definitely causes the problem to surface.  
It contains some extra debugging printouts but you can ignore them.  Or 
you can edit out the hunks that affect ehci-q.c.

Ideally, you would test this while forcing the card reader to run at
full speed, by putting a USB-1.1 hub between the monitor and the card
reader.  But if you don't have one available, don't worry -- the error
message should still appear even though it won't lead to an oops.

And of course, when you run this along with the proposed fix, the error 
message should go away.  :-)

Alan Stern



Index: usb-2.6/drivers/usb/core/hcd.c
===================================================================
--- usb-2.6.orig/drivers/usb/core/hcd.c
+++ usb-2.6/drivers/usb/core/hcd.c
@@ -1627,6 +1627,11 @@ rescan:
 	}
 	spin_unlock_irq(&hcd_urb_list_lock);
 
+	printk(KERN_INFO "flush delay %02x\n", ep->desc.bEndpointAddress);
+	local_irq_disable();
+	mdelay(10);
+	local_irq_enable();
+
 	/* Wait until the endpoint queue is completely empty */
 	while (!list_empty (&ep->urb_list)) {
 		spin_lock_irq(&hcd_urb_list_lock);
Index: usb-2.6/drivers/usb/host/ehci-hcd.c
===================================================================
--- usb-2.6.orig/drivers/usb/host/ehci-hcd.c
+++ usb-2.6/drivers/usb/host/ehci-hcd.c
@@ -74,7 +74,7 @@ static const char	hcd_name [] = "ehci_hc
 #endif
 
 /* magic numbers that can affect system performance */
-#define	EHCI_TUNE_CERR		3	/* 0-3 qtd retries; 0 == don't stop */
+#define	EHCI_TUNE_CERR		0	/* 0-3 qtd retries; 0 == don't stop */
 #define	EHCI_TUNE_RL_HS		4	/* nak throttle; see 4.9 */
 #define	EHCI_TUNE_RL_TT		0
 #define	EHCI_TUNE_MULT_HS	1	/* 1-3 transactions/uframe; 4.10.3 */
Index: usb-2.6/drivers/usb/host/ehci-q.c
===================================================================
--- usb-2.6.orig/drivers/usb/host/ehci-q.c
+++ usb-2.6/drivers/usb/host/ehci-q.c
@@ -272,6 +272,9 @@ __acquires(ehci->lock)
 
 	if (unlikely(urb->unlinked)) {
 		COUNT(ehci->stats.unlink);
+		if (urb->unlinked == -ESHUTDOWN)
+		printk(KERN_INFO "give back SHUTDOWN URB %02x\n",
+urb->ep->desc.bEndpointAddress);
 	} else {
 		/* report non-error and short read status as zero */
 		if (status == -EINPROGRESS || status == -EREMOTEIO)
@@ -334,6 +337,8 @@ qh_completions (struct ehci_hcd *ehci, s
 	state = qh->qh_state;
 	qh->qh_state = QH_STATE_COMPLETING;
 	stopped = (state == QH_STATE_IDLE);
+	if (stopped)
+		printk(KERN_INFO "Scan stopped qh\n");
 
  rescan:
 	last = NULL;
@@ -1231,6 +1236,7 @@ static void start_unlink_async (struct e
 	qh->qh_state = QH_STATE_UNLINK;
 	ehci->reclaim = qh = qh_get (qh);
 
+	printk(KERN_INFO "Start async unlink\n");
 	prev = ehci->async;
 	while (prev->qh_next.qh != qh)
 		prev = prev->qh_next.qh;
Index: usb-2.6/drivers/usb/core/message.c
===================================================================
--- usb-2.6.orig/drivers/usb/core/message.c
+++ usb-2.6/drivers/usb/core/message.c
@@ -323,8 +323,13 @@ static void sg_complete(struct urb *urb)
 	/* on the last completion, signal usb_sg_wait() */
 	io->bytes += urb->actual_length;
 	io->count--;
-	if (!io->count)
+	if (!io->count) {
+		if (status == -ESHUTDOWN) {
+			printk(KERN_INFO "sg completion delay\n");
+			mdelay(50);
+		}
 		complete(&io->complete);
+	}
 
 	spin_unlock(&io->lock);
 }

Re: 2.6.36-rc7: NULL pointer dereference in ehci_clear_tt_buffer_complete

[Stefan Richter]

Alan Stern wrote:
> Okay, here's a patch which definitely causes the problem to surface.  
> It contains some extra debugging printouts but you can ignore them.  Or 
> you can edit out the hunks that affect ehci-q.c.
> 
> Ideally, you would test this while forcing the card reader to run at
> full speed, by putting a USB-1.1 hub between the monitor and the card
> reader.  But if you don't have one available, don't worry -- the error
> message should still appear even though it won't lead to an oops.
> 
> And of course, when you run this along with the proposed fix, the error 
> message should go away.  :-)

Thanks, I will try it RSN, hopefully one of the next few days.
-- 
Stefan Richter
-=====-==-=- =-=- ==---
http://arcgraph.de/sr/