USB disconnects every 30 seconds (2.6.27-rc8)

USB disconnects every 30 seconds (2.6.27-rc8)

[Dave Hansen]

I'm seeing some odd USB behavior with newer kernels
(2.6.27-rc8-00062-g330f647 to be exact).  Almost exactly, every 30
seconds, one of my USB hubs disconnects.  At first, I thought it was a
hardware issue, and started swapping cables.  Then, I realized that I'd
*just* rebooted into a new kernel.  So, I booted back to the distro
kernel and these went away.

Even though my mouse is hanging off that hub, I don't seem to notice the
disconnects.

$ dmesg | grep disconnect
[ 3599.496217] usb 3-4.4.4: USB disconnect, address 122
[ 3599.677346] usb 3-4.1: USB disconnect, address 121
[ 3627.804621] usb 3-4.1: USB disconnect, address 124
[ 3628.004400] usb 3-4.4.4: USB disconnect, address 123
[ 3659.496421] usb 3-4.4.4: USB disconnect, address 126
[ 3659.676186] usb 3-4.1: USB disconnect, address 125
[ 3689.493763] usb 3-4.1: USB disconnect, address 3
[ 3689.708916] usb 3-4.4.4: USB disconnect, address 127
[ 3719.497221] usb 3-4.4.4: USB disconnect, address 7
[ 3719.684965] usb 3-4.1: USB disconnect, address 6
[ 3749.496323] usb 3-4.1: USB disconnect, address 9
[ 3749.691180] usb 3-4.4.4: USB disconnect, address 8

Full dmesg and .config:

http://sr71.net/~dave/linux/config-10-03-2008.1.txt
http://sr71.net/~dave/linux/dmesg-10-03-2008.1.log

The last one I tried before this was -rc3, and it appears to be OK.  The
Ubuntu 2.6.24-19-generic kernel also appears not to have this issue.

A quick scan of LKML and linux-usb didn't turn up anything similar.

The machine is a Lenovo T61 plugged into the Lenovo dock.  At this
point, the only thing plugged into the suspect hub is my mouse.

-- Dave

Re: USB disconnects every 30 seconds (2.6.27-rc8)

[Alan Stern]

On Fri, 3 Oct 2008, Dave Hansen wrote:

> I'm seeing some odd USB behavior with newer kernels
> (2.6.27-rc8-00062-g330f647 to be exact).  Almost exactly, every 30
> seconds, one of my USB hubs disconnects.

Actually two of the hubs disconnect: 3-4.1 and 3-4.4.4.  Neither is 
beneath the other.

>  At first, I thought it was a
> hardware issue, and started swapping cables.  Then, I realized that I'd
> *just* rebooted into a new kernel.  So, I booted back to the distro
> kernel and these went away.
> 
> Even though my mouse is hanging off that hub,

No it isn't.  The mouse is 3-4.4.1, which is not below either 3-4.1 or 
3-4.4.4.

> I don't seem to notice the
> disconnects.
> 
> $ dmesg | grep disconnect
> [ 3599.496217] usb 3-4.4.4: USB disconnect, address 122
> [ 3599.677346] usb 3-4.1: USB disconnect, address 121
> [ 3627.804621] usb 3-4.1: USB disconnect, address 124
> [ 3628.004400] usb 3-4.4.4: USB disconnect, address 123
> [ 3659.496421] usb 3-4.4.4: USB disconnect, address 126
> [ 3659.676186] usb 3-4.1: USB disconnect, address 125
> [ 3689.493763] usb 3-4.1: USB disconnect, address 3
> [ 3689.708916] usb 3-4.4.4: USB disconnect, address 127
> [ 3719.497221] usb 3-4.4.4: USB disconnect, address 7
> [ 3719.684965] usb 3-4.1: USB disconnect, address 6
> [ 3749.496323] usb 3-4.1: USB disconnect, address 9
> [ 3749.691180] usb 3-4.4.4: USB disconnect, address 8
> 
> Full dmesg and .config:
> 
> http://sr71.net/~dave/linux/config-10-03-2008.1.txt
> http://sr71.net/~dave/linux/dmesg-10-03-2008.1.log
> 
> The last one I tried before this was -rc3, and it appears to be OK.  The
> Ubuntu 2.6.24-19-generic kernel also appears not to have this issue.
> 
> A quick scan of LKML and linux-usb didn't turn up anything similar.
> 
> The machine is a Lenovo T61 plugged into the Lenovo dock.  At this
> point, the only thing plugged into the suspect hub is my mouse.

In fact, nothing is plugged into either of the hubs.

In theory this could be caused by a problem in the dock.  But it would 
be better to get more information before trying to pin down the cause.

You should use usbmon (see Documentation/usb/usbmon.txt) to record a 
trace of everything happening on bus 3.  And to keep things simple, you 
should unplug all the USB devices except for one of the magical 
disappearing hubs.

Alan Stern

Re: USB disconnects every 30 seconds (2.6.27-rc8)

[Dave Hansen]

On Fri, 2008-10-03 at 14:40 -0400, Alan Stern wrote:
> On Fri, 3 Oct 2008, Dave Hansen wrote:
> > I'm seeing some odd USB behavior with newer kernels
> > (2.6.27-rc8-00062-g330f647 to be exact).  Almost exactly, every 30
> > seconds, one of my USB hubs disconnects.
> 
> Actually two of the hubs disconnect: 3-4.1 and 3-4.4.4.  Neither is 
> beneath the other.

Yeah, it's a "7-port hub".  I assume that means that it's a pair of
4-porters plugged together somehow.  

It is this exact model:

	http://store.pchcables.com/usb7posepohu.html

> >  At first, I thought it was a
> > hardware issue, and started swapping cables.  Then, I realized that I'd
> > *just* rebooted into a new kernel.  So, I booted back to the distro
> > kernel and these went away.
> > 
> > Even though my mouse is hanging off that hub,
> 
> No it isn't.  The mouse is 3-4.4.1, which is not below either 3-4.1 or 
> 3-4.4.4.

Huh, that's odd.

The T61 has two (empty) USB ports on the left, one on the right, and 4
on the dock.  The configuration I've had so far is the 7-port hub
plugged into one of the four ports on the back of the T61.

> > The machine is a Lenovo T61 plugged into the Lenovo dock.  At this
> > point, the only thing plugged into the suspect hub is my mouse.
> 
> In fact, nothing is plugged into either of the hubs.
> 
> In theory this could be caused by a problem in the dock.  But it would 
> be better to get more information before trying to pin down the cause.
> 
> You should use usbmon (see Documentation/usb/usbmon.txt) to record a 
> trace of everything happening on bus 3.  And to keep things simple, you 
> should unplug all the USB devices except for one of the magical 
> disappearing hubs.

Unfortunately, the disconnects don't happen unless both my 7-port hub
and the mouse are connected.  So, I've disconnected everything but those
two things.  I also plugged the mouse into the single port on the right
side of the T61 instead of the dock.

usbmon output: http://sr71.net/~dave/linux/1.mon.out

I've also attached appended the corresponding dmesg with annotations of
what I did when.

plug in mouse:
Oct  3 11:53:51 nimitz kernel: [ 8253.306987] usb 2-1: new low speed USB device using uhci_hcd and address 4
Oct  3 11:53:51 nimitz kernel: [ 8253.420284] usb 2-1: configuration #1 chosen from 1 choice
Oct  3 11:53:52 nimitz kernel: [ 8253.476663] input: Logitech USB Receiver as /devices/pci0000:00/0000:00:1a.1/usb2/2-1/2-1:1.0/input/input13
Oct  3 11:53:52 nimitz kernel: [ 8253.493970] input: USB HID v1.10 Mouse [Logitech USB Receiver] on usb-0000:00:1a.1-1
plug in '7 port' hub:
Oct  3 11:54:26 nimitz kernel: [ 8288.132987] usb 3-4.3: new high speed USB device using ehci_hcd and address 47
Oct  3 11:54:26 nimitz kernel: [ 8288.188960] usb 3-4.3: configuration #1 chosen from 1 choice
Oct  3 11:54:26 nimitz kernel: [ 8288.189371] hub 3-4.3:1.0: USB hub found
Oct  3 11:54:26 nimitz kernel: [ 8288.189669] hub 3-4.3:1.0: 4 ports detected
Oct  3 11:54:26 nimitz kernel: [ 8288.339300] usb 3-4.3.4: new high speed USB device using ehci_hcd and address 48
Oct  3 11:54:26 nimitz kernel: [ 8288.395323] usb 3-4.3.4: configuration #1 chosen from 1 choice
Oct  3 11:54:26 nimitz kernel: [ 8288.395611] hub 3-4.3.4:1.0: USB hub found
Oct  3 11:54:26 nimitz kernel: [ 8288.395928] hub 3-4.3.4:1.0: 4 ports detected
'hub disconnects:' (I didn't do anything physically here)
Oct  3 11:54:52 nimitz kernel: [ 8313.567487] usb 3-4.3: USB disconnect, address 47
Oct  3 11:54:52 nimitz kernel: [ 8313.567492] usb 3-4.3.4: USB disconnect, address 48
Oct  3 11:54:52 nimitz kernel: [ 8313.619115] usb 3-4.3: new high speed USB device using ehci_hcd and address 49
Oct  3 11:54:52 nimitz kernel: [ 8313.675618] usb 3-4.3: configuration #1 chosen from 1 choice
Oct  3 11:54:52 nimitz kernel: [ 8313.675887] hub 3-4.3:1.0: USB hub found
Oct  3 11:54:52 nimitz kernel: [ 8313.676232] hub 3-4.3:1.0: 4 ports detected
Oct  3 11:54:52 nimitz kernel: [ 8313.823367] usb 3-4.3.4: new high speed USB device using ehci_hcd and address 50
Oct  3 11:54:52 nimitz kernel: [ 8313.880913] usb 3-4.3.4: configuration #1 chosen from 1 choice
Oct  3 11:54:52 nimitz kernel: [ 8313.881140] hub 3-4.3.4:1.0: USB hub found
Oct  3 11:54:52 nimitz kernel: [ 8313.881485] hub 3-4.3.4:1.0: 4 ports detected
Oct  3 11:55:22 nimitz kernel: [ 8343.572344] usb 3-4.3: USB disconnect, address 49
Oct  3 11:55:22 nimitz kernel: [ 8343.572355] usb 3-4.3.4: USB disconnect, address 50
Oct  3 11:55:22 nimitz kernel: [ 8343.695579] usb 3-4.3: new high speed USB device using ehci_hcd and address 51
Oct  3 11:55:22 nimitz kernel: [ 8343.754283] usb 3-4.3: configuration #1 chosen from 1 choice
Oct  3 11:55:22 nimitz kernel: [ 8343.754598] hub 3-4.3:1.0: USB hub found
Oct  3 11:55:22 nimitz kernel: [ 8343.754923] hub 3-4.3:1.0: 4 ports detected
Oct  3 11:55:22 nimitz kernel: [ 8343.908841] usb 3-4.3.4: new high speed USB device using ehci_hcd and address 52
Oct  3 11:55:22 nimitz kernel: [ 8343.964966] usb 3-4.3.4: configuration #1 chosen from 1 choice
Oct  3 11:55:22 nimitz kernel: [ 8343.965247] hub 3-4.3.4:1.0: USB hub found

-- Dave

Re: USB disconnects every 30 seconds (2.6.27-rc8)

[Alan Stern]

On Fri, 3 Oct 2008, Dave Hansen wrote:

> Yeah, it's a "7-port hub".  I assume that means that it's a pair of
> 4-porters plugged together somehow.  

It turns out that's exactly right.

> Unfortunately, the disconnects don't happen unless both my 7-port hub
> and the mouse are connected.  So, I've disconnected everything but those
> two things.  I also plugged the mouse into the single port on the right
> side of the T61 instead of the dock.
> 
> usbmon output: http://sr71.net/~dave/linux/1.mon.out

The usbmon trace answers a few questions.  And it raises one other.

> I've also attached appended the corresponding dmesg with annotations of
> what I did when.
> 
> plug in mouse:
> Oct  3 11:53:51 nimitz kernel: [ 8253.306987] usb 2-1: new low speed USB device using uhci_hcd and address 4
> Oct  3 11:53:51 nimitz kernel: [ 8253.420284] usb 2-1: configuration #1 chosen from 1 choice
> Oct  3 11:53:52 nimitz kernel: [ 8253.476663] input: Logitech USB Receiver as /devices/pci0000:00/0000:00:1a.1/usb2/2-1/2-1:1.0/input/input13
> Oct  3 11:53:52 nimitz kernel: [ 8253.493970] input: USB HID v1.10 Mouse [Logitech USB Receiver] on usb-0000:00:1a.1-1

That was more or less normal.

> plug in '7 port' hub:
> Oct  3 11:54:26 nimitz kernel: [ 8288.132987] usb 3-4.3: new high speed USB device using ehci_hcd and address 47
> Oct  3 11:54:26 nimitz kernel: [ 8288.188960] usb 3-4.3: configuration #1 chosen from 1 choice
> Oct  3 11:54:26 nimitz kernel: [ 8288.189371] hub 3-4.3:1.0: USB hub found
> Oct  3 11:54:26 nimitz kernel: [ 8288.189669] hub 3-4.3:1.0: 4 ports detected
> Oct  3 11:54:26 nimitz kernel: [ 8288.339300] usb 3-4.3.4: new high speed USB device using ehci_hcd and address 48
> Oct  3 11:54:26 nimitz kernel: [ 8288.395323] usb 3-4.3.4: configuration #1 chosen from 1 choice
> Oct  3 11:54:26 nimitz kernel: [ 8288.395611] hub 3-4.3.4:1.0: USB hub found
> Oct  3 11:54:26 nimitz kernel: [ 8288.395928] hub 3-4.3.4:1.0: 4 ports detected

As you can see, it is really two 4-port hubs: 3-4.3 and 3-4.3.4 
(which is connected to port 4 of 4.3).

> 'hub disconnects:' (I didn't do anything physically here)
> Oct  3 11:54:52 nimitz kernel: [ 8313.567487] usb 3-4.3: USB disconnect, address 47
> Oct  3 11:54:52 nimitz kernel: [ 8313.567492] usb 3-4.3.4: USB disconnect, address 48

Okay.  You didn't do anything, but _something_ did.  Probably a program
running on your computer that checks out all the usb devices every 30
seconds.  The usbmon trace clearly shows every suspended hub (which is
all but the one the mouse is plugged into) being woken up at 30-second
intervals.

Suspiciously enough, at the same time a vendor-specific request is sent 
to the mouse.  This, together with the fact that the disconnects occur 
only when the mouse is plugged in, strongly suggests that some program 
is trying to use the mouse and is doing something bad every 30 seconds.

Below is a patch you can apply; it may indicate which program is 
responsible.  In order to use it you'll have to do:

	echo 1 >/sys/module/usbcore/parameters/usbfs_snoop

before plugging in the mouse.

The next question is why the disconnects?  This is harder to explain.  
It's evident in the trace that there's something wrong with the timing 
code in your computer.  This shows up in several places, most clearly 
when the 7-port hub is resumed.

A resume works as follows: The computer sends a Clear-Port-Suspend
request to the hub's parent and then waits at least 25 milliseconds for 
the suspend to end.  In your trace, that delay lasts only 16 ms, which
wasn't long enough.  The suspend was still in progress, so the kernel 
decided something was wrong and disconnected the 7-port hub.  You can 
see it here (the second field on each line is a timestamp in 
microseconds):

f6194900 1490306395 S Co:3:002:0 s 23 01 0002 0003 0000 0
f6194900 1490306515 C Co:3:002:0 0 0
f6194900 1490322567 S Ci:3:002:0 s a3 00 0000 0003 0004 4 <
f6194900 1490322614 C Ci:3:002:0 0 4 = 07050000
f6194900 1490330540 S Co:3:002:0 s 23 01 0001 0003 0000 0
f6194900 1490330614 C Co:3:002:0 0 0

The first two lines show the Clear-Port-Suspend request being sent and
completing normally.  The third and fourth lines show a Get-Port-Status
request; the difference in times between the second and third lines is
1490322567 - 1490306515 = 16052 us, or about 16 ms.  But the source
code for that delay says:

	msleep(25);

so something is badly wrong.  And sure enough, the status value
07050000 indicates that the Suspend feature is still turned on.  The
last two lines show the hub being logically disconnected.

There are a number of other places in the trace where delays are
shorter than they should be.  This is out of my area of expertise, so 
I'm CC'ing Thomas Gleixner.  With luck he'll be able to help.

Thomas, the background for this problem is available here:

	http://marc.info/?l=linux-kernel&m=122305738430115&w=2

Alan Stern



Index: usb-2.6/drivers/usb/core/devio.c
===================================================================
--- usb-2.6.orig/drivers/usb/core/devio.c
+++ usb-2.6/drivers/usb/core/devio.c
@@ -625,6 +625,8 @@ static int usbdev_open(struct inode *ino
 	smp_wmb();
 	list_add_tail(&ps->list, &dev->filelist);
 	file->private_data = ps;
+	snoop(&dev->dev, "opened by process %d: %s\n", task_pid_nr(current),
+			current->comm);
  out:
 	if (ret) {
 		kfree(ps);

Re: USB disconnects every 30 seconds (2.6.27-rc8)

[Thomas Gleixner]

On Fri, 3 Oct 2008, Alan Stern wrote:
> On Fri, 3 Oct 2008, Dave Hansen wrote:
> There are a number of other places in the trace where delays are
> shorter than they should be.  This is out of my area of expertise, so 
> I'm CC'ing Thomas Gleixner.  With luck he'll be able to help.
> 
> Thomas, the background for this problem is available here:
> 
> 	http://marc.info/?l=linux-kernel&m=122305738430115&w=2

Is NOHZ and HIGHRES disabled on those kernels? Hugh spotted a typo in
that code today. Fix is below. It causes jiffies to increment too fast
which explains your short delays.

Thanks,

	tglx
---
diff --git a/kernel/time/tick-broadcast.c b/kernel/time/tick-broadcast.c
index bd70345..cb01cd8 100644
--- a/kernel/time/tick-broadcast.c
+++ b/kernel/time/tick-broadcast.c
@@ -235,7 +235,8 @@ static void tick_do_broadcast_on_off(void *why)
 	case CLOCK_EVT_NOTIFY_BROADCAST_FORCE:
 		if (!cpu_isset(cpu, tick_broadcast_mask)) {
 			cpu_set(cpu, tick_broadcast_mask);
-			if (bc->mode == TICKDEV_MODE_PERIODIC)
+			if (tick_broadcast_device.mode ==
+			    TICKDEV_MODE_PERIODIC)
 				clockevents_shutdown(dev);
 		}
 		if (*reason == CLOCK_EVT_NOTIFY_BROADCAST_FORCE)
@@ -245,7 +246,8 @@ static void tick_do_broadcast_on_off(void *why)
 		if (!tick_broadcast_force &&
 		    cpu_isset(cpu, tick_broadcast_mask)) {
 			cpu_clear(cpu, tick_broadcast_mask);
-			if (bc->mode == TICKDEV_MODE_PERIODIC)
+			if (tick_broadcast_device.mode ==
+			    TICKDEV_MODE_PERIODIC)
 				tick_setup_periodic(dev, 0);
 		}
 		break;

Re: USB disconnects every 30 seconds (2.6.27-rc8)

[Dave Hansen]

On Sat, 2008-10-04 at 00:24 +0200, Thomas Gleixner wrote:
> On Fri, 3 Oct 2008, Alan Stern wrote:
> > On Fri, 3 Oct 2008, Dave Hansen wrote:
> > There are a number of other places in the trace where delays are
> > shorter than they should be.  This is out of my area of expertise, so 
> > I'm CC'ing Thomas Gleixner.  With luck he'll be able to help.
> > 
> > Thomas, the background for this problem is available here:
> > 
> > 	http://marc.info/?l=linux-kernel&m=122305738430115&w=2
> 
> Is NOHZ and HIGHRES disabled on those kernels? Hugh spotted a typo in
> that code today. Fix is below. It causes jiffies to increment too fast
> which explains your short delays.

Here's my config:

http://sr71.net/~dave/linux/config-10-03-2008.1.txt

No NOHZ or HIGHRES.  Is that what you meant?  

-- Dave

Re: USB disconnects every 30 seconds (2.6.27-rc8)

[Dave Hansen]

OK, here's output with both Thomas/Hugh's timing fix as well as the USB
snooping turned on.  The disconnects still happen, but I did get some
good snoop output:

Oct  3 16:01:59 nimitz kernel: [  180.273883] usb usb7: opened by process 6485: hald-addon-usb-
Oct  3 16:01:59 nimitz kernel: [  180.273894] usb usb7: usbdev_ioctl: CONNECTINFO
Oct  3 16:01:59 nimitz kernel: [  180.273935] usb usb7: opened by process 6485: hald-addon-usb-

grepping for hald:
dave@nimitz:~$ ps aux | grep hald
111       6407  0.5  0.1   6340  4352 ?        Ss   15:59   0:00 /usr/sbin/hald
root      6411  0.0  0.0   3348  1152 ?        S    15:59   0:00 hald-runner
root      6485  0.1  0.0   2996  1140 ?        S    15:59   0:00 hald-addon-usb-csr: listening on 'MX700 Optical Mouse'
...

If I kill off 'hald-addon-usb-csr', then the resets stop happening.
Restart hal, and they come back.  

Oct  3 16:01:59 nimitz kernel: [  180.273883] usb usb7: opened by process 6485: hald-addon-usb-
Oct  3 16:01:59 nimitz kernel: [  180.273894] usb usb7: usbdev_ioctl: CONNECTINFO
Oct  3 16:01:59 nimitz kernel: [  180.273935] usb usb7: opened by process 6485: hald-addon-usb-
Oct  3 16:01:59 nimitz kernel: [  180.273940] usb usb7: usbdev_ioctl: IOCTL
Oct  3 16:01:59 nimitz kernel: [  180.392126] usb 3-4: opened by process 6485: hald-addon-usb-
Oct  3 16:01:59 nimitz kernel: [  180.393185] usb 3-4.3: USB disconnect, address 16
Oct  3 16:01:59 nimitz kernel: [  180.393191] usb 3-4.3.4: USB disconnect, address 17
Oct  3 16:01:59 nimitz kernel: [  180.437913] usb 3-4.3: new high speed USB device using ehci_hcd and address 18
Oct  3 16:01:59 nimitz kernel: [  180.494705] usb 3-4.3: configuration #1 chosen from 1 choice
Oct  3 16:01:59 nimitz kernel: [  180.495101] hub 3-4.3:1.0: USB hub found
Oct  3 16:01:59 nimitz kernel: [  180.495409] hub 3-4.3:1.0: 4 ports detected
Oct  3 16:01:59 nimitz kernel: [  180.600101] usb 3-4: usbdev_ioctl: CONNECTINFO
Oct  3 16:01:59 nimitz kernel: [  180.600144] usb usb3: opened by process 6485: hald-addon-usb-
Oct  3 16:01:59 nimitz kernel: [  180.600147] usb usb3: usbdev_ioctl: CONNECTINFO
Oct  3 16:01:59 nimitz kernel: [  180.600167] usb 3-4: opened by process 6485: hald-addon-usb-
Oct  3 16:01:59 nimitz kernel: [  180.600170] usb 3-4: usbdev_ioctl: IOCTL
Oct  3 16:01:59 nimitz kernel: [  180.600179] usb usb3: opened by process 6485: hald-addon-usb-
Oct  3 16:01:59 nimitz kernel: [  180.600182] usb usb3: usbdev_ioctl: IOCTL
Oct  3 16:01:59 nimitz kernel: [  180.619896] usb usb6: opened by process 6485: hald-addon-usb-
Oct  3 16:01:59 nimitz kernel: [  180.620387] usb usb6: usbdev_ioctl: CONNECTINFO
Oct  3 16:01:59 nimitz kernel: [  180.620766] usb usb6: opened by process 6485: hald-addon-usb-
Oct  3 16:01:59 nimitz kernel: [  180.621179] usb usb6: usbdev_ioctl: IOCTL
Oct  3 16:01:59 nimitz kernel: [  180.640068] usb usb5: opened by process 6485: hald-addon-usb-
Oct  3 16:01:59 nimitz kernel: [  180.640509] usb usb5: usbdev_ioctl: CONNECTINFO
Oct  3 16:01:59 nimitz kernel: [  180.640866] usb usb5: opened by process 6485: hald-addon-usb-
Oct  3 16:01:59 nimitz kernel: [  180.641278] usb usb5: usbdev_ioctl: IOCTL
Oct  3 16:01:59 nimitz kernel: [  180.641599] usb 4-1: opened by process 6485: hald-addon-usb-
Oct  3 16:01:59 nimitz kernel: [  180.642006] usb 4-1: usbdev_ioctl: CONNECTINFO
Oct  3 16:01:59 nimitz kernel: [  180.642347] usb usb4: opened by process 6485: hald-addon-usb-
Oct  3 16:01:59 nimitz kernel: [  180.642757] usb usb4: usbdev_ioctl: CONNECTINFO
Oct  3 16:01:59 nimitz kernel: [  180.643108] usb 4-1: opened by process 6485: hald-addon-usb-
Oct  3 16:01:59 nimitz kernel: [  180.643524] usb 4-1: usbdev_ioctl: IOCTL
Oct  3 16:01:59 nimitz kernel: [  180.643872] usb usb4: opened by process 6485: hald-addon-usb-
Oct  3 16:01:59 nimitz kernel: [  180.644159] usb 3-4.3.4: new high speed USB device using ehci_hcd and address 19
Oct  3 16:01:59 nimitz kernel: [  180.644856] usb usb4: usbdev_ioctl: IOCTL
Oct  3 16:01:59 nimitz kernel: [  180.645180] usb 2-1: opened by process 6485: hald-addon-usb-
Oct  3 16:01:59 nimitz kernel: [  180.645612] usb 2-1: usbdev_ioctl: CONNECTINFO
Oct  3 16:01:59 nimitz kernel: [  180.645954] usb usb2: opened by process 6485: hald-addon-usb-
Oct  3 16:01:59 nimitz kernel: [  180.646531] usb usb2: usbdev_ioctl: CONNECTINFO
Oct  3 16:01:59 nimitz kernel: [  180.646888] usb 2-1: opened by process 6485: hald-addon-usb-
Oct  3 16:01:59 nimitz kernel: [  180.647314] usb 2-1: usbdev_ioctl: IOCTL
Oct  3 16:01:59 nimitz kernel: [  180.647640] usb usb2: opened by process 6485: hald-addon-usb-
Oct  3 16:01:59 nimitz kernel: [  180.648106] usb usb2: usbdev_ioctl: IOCTL
Oct  3 16:01:59 nimitz kernel: [  180.667895] usb usb1: opened by process 6485: hald-addon-usb-
Oct  3 16:01:59 nimitz kernel: [  180.668340] usb usb1: usbdev_ioctl: CONNECTINFO
Oct  3 16:01:59 nimitz kernel: [  180.668689] usb usb1: opened by process 6485: hald-addon-usb-
Oct  3 16:01:59 nimitz kernel: [  180.669101] usb usb1: usbdev_ioctl: IOCTL
Oct  3 16:01:59 nimitz kernel: [  180.669420] usb 2-1: opened by process 6485: hald-addon-usb-
Oct  3 16:01:59 nimitz kernel: [  180.669823] usb 2-1: usbdev_ioctl: CONTROL
Oct  3 16:01:59 nimitz kernel: [  180.669827] usb 2-1: control read: bRequest=09 bRrequestType=c0 wValue=0003 wIndex=0000 wLength=0008
Oct  3 16:01:59 nimitz kernel: [  180.673036] usb 2-1: control read: data 20 3d 8b 45 05 0b 01 ee 
Oct  3 16:01:59 nimitz kernel: [  180.701219] usb 3-4.3.4: configuration #1 chosen from 1 choice
Oct  3 16:01:59 nimitz kernel: [  180.701552] hub 3-4.3.4:1.0: USB hub found
Oct  3 16:01:59 nimitz kernel: [  180.701905] hub 3-4.3.4:1.0: 4 ports detected

-- Dave

Re: USB disconnects every 30 seconds (2.6.27-rc8)

[Marcel Holtmann]

Hi Dave,

> OK, here's output with both Thomas/Hugh's timing fix as well as the USB
> snooping turned on.  The disconnects still happen, but I did get some
> good snoop output:
> 
> Oct  3 16:01:59 nimitz kernel: [  180.273883] usb usb7: opened by process 6485: hald-addon-usb-
> Oct  3 16:01:59 nimitz kernel: [  180.273894] usb usb7: usbdev_ioctl: CONNECTINFO
> Oct  3 16:01:59 nimitz kernel: [  180.273935] usb usb7: opened by process 6485: hald-addon-usb-
> 
> grepping for hald:
> dave@nimitz:~$ ps aux | grep hald
> 111       6407  0.5  0.1   6340  4352 ?        Ss   15:59   0:00 /usr/sbin/hald
> root      6411  0.0  0.0   3348  1152 ?        S    15:59   0:00 hald-runner
> root      6485  0.1  0.0   2996  1140 ?        S    15:59   0:00 hald-addon-usb-csr: listening on 'MX700 Optical Mouse'
> ...
> 
> If I kill off 'hald-addon-usb-csr', then the resets stop happening.

the addon is for some weird handling of CSR based HID devices in their
Bluetooth/USB HID proxy devices or so.

Alan, that is the vendor request you saw. Don't ask me what exactly this
one does. I really have no idea.

Regards

Marcel

Re: USB disconnects every 30 seconds (2.6.27-rc8)

[Alan Stern]

On Sat, 4 Oct 2008, Marcel Holtmann wrote:

> Hi Dave,

> the addon is for some weird handling of CSR based HID devices in their
> Bluetooth/USB HID proxy devices or so.
> 
> Alan, that is the vendor request you saw. Don't ask me what exactly this
> one does. I really have no idea.

I wasn't going to.  :-)

Alan Stern

Re: USB disconnects every 30 seconds (2.6.27-rc8)

[Alan Stern]

On Fri, 3 Oct 2008, Dave Hansen wrote:

> OK, here's output with both Thomas/Hugh's timing fix as well as the USB
> snooping turned on.  The disconnects still happen, but I did get some
> good snoop output:
> 
> Oct  3 16:01:59 nimitz kernel: [  180.273883] usb usb7: opened by process 6485: hald-addon-usb-
> Oct  3 16:01:59 nimitz kernel: [  180.273894] usb usb7: usbdev_ioctl: CONNECTINFO
> Oct  3 16:01:59 nimitz kernel: [  180.273935] usb usb7: opened by process 6485: hald-addon-usb-
> 
> grepping for hald:
> dave@nimitz:~$ ps aux | grep hald
> 111       6407  0.5  0.1   6340  4352 ?        Ss   15:59   0:00 /usr/sbin/hald
> root      6411  0.0  0.0   3348  1152 ?        S    15:59   0:00 hald-runner
> root      6485  0.1  0.0   2996  1140 ?        S    15:59   0:00 hald-addon-usb-csr: listening on 'MX700 Optical Mouse'
> ...
> 
> If I kill off 'hald-addon-usb-csr', then the resets stop happening.
> Restart hal, and they come back.  

There's probably a setting for hal which will prevent this constant 
probing.

> Oct  3 16:01:59 nimitz kernel: [  180.273883] usb usb7: opened by process 6485: hald-addon-usb-
> Oct  3 16:01:59 nimitz kernel: [  180.273894] usb usb7: usbdev_ioctl: CONNECTINFO
> Oct  3 16:01:59 nimitz kernel: [  180.273935] usb usb7: opened by process 6485: hald-addon-usb-
> Oct  3 16:01:59 nimitz kernel: [  180.273940] usb usb7: usbdev_ioctl: IOCTL
> Oct  3 16:01:59 nimitz kernel: [  180.392126] usb 3-4: opened by process 6485: hald-addon-usb-
> Oct  3 16:01:59 nimitz kernel: [  180.393185] usb 3-4.3: USB disconnect, address 16
> Oct  3 16:01:59 nimitz kernel: [  180.393191] usb 3-4.3.4: USB disconnect, address 17
> Oct  3 16:01:59 nimitz kernel: [  180.437913] usb 3-4.3: new high speed USB device using ehci_hcd and address 18
> Oct  3 16:01:59 nimitz kernel: [  180.494705] usb 3-4.3: configuration #1 chosen from 1 choice
> Oct  3 16:01:59 nimitz kernel: [  180.495101] hub 3-4.3:1.0: USB hub found
> Oct  3 16:01:59 nimitz kernel: [  180.495409] hub 3-4.3:1.0: 4 ports detected
> Oct  3 16:01:59 nimitz kernel: [  180.600101] usb 3-4: usbdev_ioctl: CONNECTINFO
> Oct  3 16:01:59 nimitz kernel: [  180.600144] usb usb3: opened by process 6485: hald-addon-usb-
> Oct  3 16:01:59 nimitz kernel: [  180.600147] usb usb3: usbdev_ioctl: CONNECTINFO
> Oct  3 16:01:59 nimitz kernel: [  180.600167] usb 3-4: opened by process 6485: hald-addon-usb-
> Oct  3 16:01:59 nimitz kernel: [  180.600170] usb 3-4: usbdev_ioctl: IOCTL

Without a usbmon log, I can't tell what may still be going wrong.

Alan Stern

Re: USB disconnects every 30 seconds (2.6.27-rc8)

[Dave Hansen]

On Sat, 2008-10-04 at 14:12 -0400, Alan Stern wrote:
> > Oct  3 16:01:59 nimitz kernel: [  180.273883] usb usb7: opened by process 6485: hald-addon-usb-
> > Oct  3 16:01:59 nimitz kernel: [  180.273894] usb usb7: usbdev_ioctl: CONNECTINFO
> > Oct  3 16:01:59 nimitz kernel: [  180.273935] usb usb7: opened by process 6485: hald-addon-usb-
> > Oct  3 16:01:59 nimitz kernel: [  180.273940] usb usb7: usbdev_ioctl: IOCTL
> > Oct  3 16:01:59 nimitz kernel: [  180.392126] usb 3-4: opened by process 6485: hald-addon-usb-
> > Oct  3 16:01:59 nimitz kernel: [  180.393185] usb 3-4.3: USB disconnect, address 16
> > Oct  3 16:01:59 nimitz kernel: [  180.393191] usb 3-4.3.4: USB disconnect, address 17
> > Oct  3 16:01:59 nimitz kernel: [  180.437913] usb 3-4.3: new high speed USB device using ehci_hcd and address 18
> > Oct  3 16:01:59 nimitz kernel: [  180.494705] usb 3-4.3: configuration #1 chosen from 1 choice
> > Oct  3 16:01:59 nimitz kernel: [  180.495101] hub 3-4.3:1.0: USB hub found
> > Oct  3 16:01:59 nimitz kernel: [  180.495409] hub 3-4.3:1.0: 4 ports detected
> > Oct  3 16:01:59 nimitz kernel: [  180.600101] usb 3-4: usbdev_ioctl: CONNECTINFO
> > Oct  3 16:01:59 nimitz kernel: [  180.600144] usb usb3: opened by process 6485: hald-addon-usb-
> > Oct  3 16:01:59 nimitz kernel: [  180.600147] usb usb3: usbdev_ioctl: CONNECTINFO
> > Oct  3 16:01:59 nimitz kernel: [  180.600167] usb 3-4: opened by process 6485: hald-addon-usb-
> > Oct  3 16:01:59 nimitz kernel: [  180.600170] usb 3-4: usbdev_ioctl: IOCTL
> 
> Without a usbmon log, I can't tell what may still be going wrong.

This log should have recorded what was going on there.  Was there
something else that I should be capturing with usbmon that I missed?

http://sr71.net/~dave/linux/1.mon.out


-- Dave

Re: USB disconnects every 30 seconds (2.6.27-rc8)

[Alan Stern]

On Sun, 5 Oct 2008, Dave Hansen wrote:

> On Sat, 2008-10-04 at 14:12 -0400, Alan Stern wrote:
> > > Oct  3 16:01:59 nimitz kernel: [  180.273883] usb usb7: opened by process 6485: hald-addon-usb-
> > > Oct  3 16:01:59 nimitz kernel: [  180.273894] usb usb7: usbdev_ioctl: CONNECTINFO
> > > Oct  3 16:01:59 nimitz kernel: [  180.273935] usb usb7: opened by process 6485: hald-addon-usb-
> > > Oct  3 16:01:59 nimitz kernel: [  180.273940] usb usb7: usbdev_ioctl: IOCTL
> > > Oct  3 16:01:59 nimitz kernel: [  180.392126] usb 3-4: opened by process 6485: hald-addon-usb-
> > > Oct  3 16:01:59 nimitz kernel: [  180.393185] usb 3-4.3: USB disconnect, address 16
> > > Oct  3 16:01:59 nimitz kernel: [  180.393191] usb 3-4.3.4: USB disconnect, address 17
> > > Oct  3 16:01:59 nimitz kernel: [  180.437913] usb 3-4.3: new high speed USB device using ehci_hcd and address 18
> > > Oct  3 16:01:59 nimitz kernel: [  180.494705] usb 3-4.3: configuration #1 chosen from 1 choice
> > > Oct  3 16:01:59 nimitz kernel: [  180.495101] hub 3-4.3:1.0: USB hub found
> > > Oct  3 16:01:59 nimitz kernel: [  180.495409] hub 3-4.3:1.0: 4 ports detected
> > > Oct  3 16:01:59 nimitz kernel: [  180.600101] usb 3-4: usbdev_ioctl: CONNECTINFO
> > > Oct  3 16:01:59 nimitz kernel: [  180.600144] usb usb3: opened by process 6485: hald-addon-usb-
> > > Oct  3 16:01:59 nimitz kernel: [  180.600147] usb usb3: usbdev_ioctl: CONNECTINFO
> > > Oct  3 16:01:59 nimitz kernel: [  180.600167] usb 3-4: opened by process 6485: hald-addon-usb-
> > > Oct  3 16:01:59 nimitz kernel: [  180.600170] usb 3-4: usbdev_ioctl: IOCTL
> > 
> > Without a usbmon log, I can't tell what may still be going wrong.
> 
> This log should have recorded what was going on there.  Was there
> something else that I should be capturing with usbmon that I missed?
> 
> http://sr71.net/~dave/linux/1.mon.out

That file is the usbmon log from back on Friday.  I need to see the
usbmon log you get with the timing fix installed.  Was that not clear?  
Without the log, I can't tell why the disconnects continue to occur
even though the timing fix should have eliminated them.

Alan Stern

Re: USB disconnects every 30 seconds (2.6.27-rc8)

[Dave Hansen]

On Sun, 2008-10-05 at 15:16 -0400, Alan Stern wrote:
> That file is the usbmon log from back on Friday.  I need to see the
> usbmon log you get with the timing fix installed.  Was that not clear?  
> Without the log, I can't tell why the disconnects continue to occur
> even though the timing fix should have eliminated them.

It looks like I didn't properly apply the timing fix when I said I did
last time.  With Thomas/Hugh's fix applied, I don't see the disconnects
any more.  I'll keep an eye out and let everyone know if they reappear.

Thanks for all the excellent debugging, everyone!

-- Dave

Re: USB disconnects every 30 seconds (2.6.27-rc8)

[Alan Stern]

On Fri, 3 Oct 2008, Alan Stern wrote:

> You should use usbmon (see Documentation/usb/usbmon.txt) to record a 
> trace of everything happening on bus 3.  And to keep things simple, you 
> should unplug all the USB devices except for one of the magical 
> disappearing hubs.

Better still, get two traces: one from each kernel.  Then they can be 
compared.

Alan Stern

Re: USB disconnects every 30 seconds (2.6.27-rc8)

[Dave Hansen]

On Fri, 2008-10-03 at 15:23 -0400, Alan Stern wrote:
> On Fri, 3 Oct 2008, Alan Stern wrote:
> > You should use usbmon (see Documentation/usb/usbmon.txt) to record a 
> > trace of everything happening on bus 3.  And to keep things simple, you 
> > should unplug all the USB devices except for one of the magical 
> > disappearing hubs.
> 
> Better still, get two traces: one from each kernel.  Then they can be 
> compared.

What should I record on the good kernel?  Just the devices being
connected?

-- Dave

Re: USB disconnects every 30 seconds (2.6.27-rc8)

[Alan Stern]

On Fri, 3 Oct 2008, Dave Hansen wrote:

> On Fri, 2008-10-03 at 15:23 -0400, Alan Stern wrote:
> > On Fri, 3 Oct 2008, Alan Stern wrote:
> > > You should use usbmon (see Documentation/usb/usbmon.txt) to record a 
> > > trace of everything happening on bus 3.  And to keep things simple, you 
> > > should unplug all the USB devices except for one of the magical 
> > > disappearing hubs.
> > 
> > Better still, get two traces: one from each kernel.  Then they can be 
> > compared.
> 
> What should I record on the good kernel?  Just the devices being
> connected?

Never mind; the first trace was good enough.

Alan Stern