On Mon, Apr 26, 2010 at 04:27:31PM -0400, Alan Stern wrote:
> On Mon, 26 Apr 2010, Sarah Sharp wrote:
>
> > On Sat, Apr 24, 2010 at 06:30:10PM -0400, Alan Stern wrote:
> > > On Fri, 23 Apr 2010, Sarah Sharp wrote:
> > > Another possibility to check out is /dev/bus/usb/. Does everything
> > > seem okay in there?
> >
> > I get errors when I cat the files that correspond to the roothub and the
> > high speed hub. I can cat the character device for the mouse:
> >
> > sarah@xanatos:~/git/kernels/xhci$ ls /dev/bus/usb/009/
> > 001 002 003
> > sarah@xanatos:~/git/kernels/xhci$ file /dev/bus/usb/009/*
> > /dev/bus/usb/009/001: character special
> > /dev/bus/usb/009/002: character special
> > /dev/bus/usb/009/003: character special
> > sarah@xanatos:~/git/kernels/xhci$ ls -l /dev/bus/usb/009/
> > total 0
> > crw-rw-r-- 1 root root 189, 1024 2010-04-26 10:16 001
> > crw-rw-r-- 1 root root 189, 1025 2010-04-26 10:16 002
> > crw-rw-r-- 1 root root 189, 1026 2010-04-26 10:17 003
> > sarah@xanatos:~/git/kernels/xhci$ sudo cat /dev/bus/usb/009/001
> > cat: /dev/bus/usb/009/001: Invalid argument
> > sarah@xanatos:~/git/kernels/xhci$ sudo cat /dev/bus/usb/009/003
> > ^R^A^@^B^@^@^@^H�U�@^R^E^@^B^@^A ^B"^@^A^A^@�1
> ^D^@^@^A^C^A^B^ !^P^A^@^A"H^@^G^E^�C^D^@
> > sarah@xanatos:~/git/kernels/xhci$ sudo cat /dev/bus/usb/009/002
> > cat: /dev/bus/usb/009/002: Invalid argument
> >
> > Nothing shows up in dmesg when this happens. If I unplug and replug in
> > the high speed hub and mouse, then they both show up in lsusb, and I can
> > cat both the 002 and 003 device files. So it seems the problem is
> > here.
>
> Yes indeed. Can you track it down?
I figured out what triggers this behavior. It's related to the roothub failing
to suspend because the xHCI driver doesn't implement it. If I unplug my
express card, and then immediately cat the roothub file, it succeeds. If I
wait a bit until the roothub fails to suspend, cat fails. The same is true of
the external hub: if I cat the file before the core attempts to suspend it, the
cat succeeds, and it fails after the core tries to suspend the hub.
> A good starting place would be
> usb_classdev_add() in core/devio.c. Look at the major and minor
> numbers in dev->dev.devt (I hate it when people use the same name
> for different things like that... David Brownell once had a statement
> that looked something like: "dev->dev.dev = pdev->dev" -- try to figure
> that out!) and make sure they agree with the major and minor numbers
> shown by "ls -l".
I had CONFIG_USB_DEVICE_CLASS turned off (it is depreciated). With that
turned on, I verified the major and minor number matches the `ls -l`
output.
> Also check out usbdev_read() in the same file. If cat's read call
> reaches that routine then it must trigger the -EINVAL return code
> somehow (I can't imagine how).
I added debugging (patch is attached). An strace of the cat and the debugging
shows that the call fails when the file is opened, in usbdev_open(), due to the
auto-resume of the device failing:
Apr 26 20:14:18 xanatos kernel: [42053.643810] Attempting to create file for usb bus 1 dev 1,minor = 189, major = 0
Apr 26 20:14:18 xanatos kernel: [42053.649729] Created file for usb bus 1 dev 1,minor = 189, major = 0
Apr 26 20:14:18 xanatos kernel: [42053.740532] hub 1-0:1.0: state 7 ports 4 chg 0000 evt 0000
Apr 26 20:14:19 xanatos kernel: [42053.931780] Called usbdev_read - pos = 0
Apr 26 20:14:19 xanatos kernel: [42053.931804] Called usbdev_read - pos = 18
Apr 26 20:14:19 xanatos kernel: [42053.931828] Called usbdev_read - pos = 26
Apr 26 20:14:19 xanatos kernel: [42053.932449] Called usbdev_read - pos = 0
Apr 26 20:14:19 xanatos kernel: [42053.932464] Called usbdev_read - pos = 18
Apr 26 20:14:19 xanatos kernel: [42053.932486] Called usbdev_read - pos = 26
Apr 26 20:14:21 xanatos kernel: [42056.157017] Called usbdev_read - pos = 0
Apr 26 20:14:21 xanatos kernel: [42056.157387] Called usbdev_read - pos = 43
Apr 26 20:14:23 xanatos kernel: [42058.816150] hub 1-0:1.0: hub_suspend
Apr 26 20:14:23 xanatos kernel: [42058.816363] usb usb1: bus auto-suspend
Apr 26 20:14:23 xanatos kernel: [42058.816370] usb usb1: bus suspend fail, err -2
Apr 26 20:14:23 xanatos kernel: [42058.816376] hub 1-0:1.0: hub_resume
Apr 26 20:14:23 xanatos kernel: [42058.816703] hub 1-0:1.0: state 7 ports 4 chg 0000 evt 0000
Apr 26 20:14:27 xanatos kernel: [42062.468948] usbdev_open: Auto-resume failed.
It seems to me that if the hub suspend failed, due to it not being
implemented, it should have been marked as being active or not
suspended, and a call to usb_autoresume_device() ought to succeed
because the device is not suspended.
> And I can't imagine how changing the descriptor parsing would affect
> any of this.
It turns out it wasn't your patch. I (more carefully) tested without
your patch and with debugging turned on, and I see the same problem. I
might have tested faster without your patch, or something. At least
that mystery is solved.
I probably didn't notice the lsusb problem because I've been turning off
CONFIG_USB_SUSPEND until just recently (after AMD sent their power
management patches) because the failed hub suspending messages get
tedious. Your patch just made me look at the lsusb output. :-/
So the question becomes, can/should we fix this in usbdev_open()? Even
if the AMD power managment patches get merged for 2.6.35, we should
probably have a fix for older kernels. Or can the power management
patches be backported, since they don't add any new APIs? It seems like
a big change to backport for a small nuisance.
Greg, thoughts?
Sarah Sharp
>From 8337eeef8d522f4acc8c9946f6a99326854bc374 Mon Sep 17 00:00:00 2001
From: Sarah Sharp <sarah.a.sharp@xxxxxxxxxxxxxxx>
Date: Mon, 26 Apr 2010 20:22:43 -0700
Subject: [PATCH] Add debugging to devio.c.
Signed-off-by: Sarah Sharp <sarah.a.sharp@xxxxxxxxxxxxxxx>
---
drivers/usb/core/devio.c | 33 +++++++++++++++++++++++++++++----
1 files changed, 29 insertions(+), 4 deletions(-)
diff --git a/drivers/usb/core/devio.c b/drivers/usb/core/devio.c
index 3466fdc..4ff5f0a 100644
--- a/drivers/usb/core/devio.c
+++ b/drivers/usb/core/devio.c
@@ -153,11 +153,14 @@ static ssize_t usbdev_read(struct file *file, char __user *buf, size_t nbytes,
int i;
pos = *ppos;
+ printk(KERN_DEBUG "Called %s - pos = %lli\n", __func__, pos);
usb_lock_device(dev);
if (!connected(ps)) {
+ printk(KERN_DEBUG "%s - USB device not connected\n", __func__);
ret = -ENODEV;
goto err;
} else if (pos < 0) {
+ printk(KERN_DEBUG "%s - Bad position %lli\n", __func__, pos);
ret = -EINVAL;
goto err;
}
@@ -177,6 +180,7 @@ static ssize_t usbdev_read(struct file *file, char __user *buf, size_t nbytes,
len = nbytes;
if (copy_to_user(buf, ((char *)&temp_desc) + pos, len)) {
ret = -EFAULT;
+ printk(KERN_DEBUG "%s - Copy to user failed\n", __func__);
goto err;
}
@@ -209,6 +213,9 @@ static ssize_t usbdev_read(struct file *file, char __user *buf, size_t nbytes,
if (copy_to_user(buf,
dev->rawdescriptors[i] + (*ppos - pos),
min(len, alloclen))) {
+ printk(KERN_DEBUG "%s - Config %i failed to copy\n"
+ "*ppos = %lli, pos = %lli\n",
+ __func__, i, *ppos, pos);
ret = -EFAULT;
goto err;
}
@@ -663,8 +670,10 @@ static int usbdev_open(struct inode *inode, struct file *file)
ret = -ENOMEM;
ps = kmalloc(sizeof(struct dev_state), GFP_KERNEL);
- if (!ps)
+ if (!ps) {
+ printk(KERN_DEBUG "usbdev_open: No memory\n");
goto out_free_ps;
+ }
ret = -ENODEV;
@@ -688,16 +697,22 @@ static int usbdev_open(struct inode *inode, struct file *file)
#endif
mutex_unlock(&usbfs_mutex);
- if (!dev)
+ if (!dev) {
+ printk(KERN_DEBUG "usbdev_open: Failed at looking up the device\n");
goto out_free_ps;
+ }
usb_lock_device(dev);
- if (dev->state == USB_STATE_NOTATTACHED)
+ if (dev->state == USB_STATE_NOTATTACHED) {
+ printk(KERN_DEBUG "usbdev_open: Device not attached.\n");
goto out_unlock_device;
+ }
ret = usb_autoresume_device(dev);
- if (ret)
+ if (ret) {
+ printk(KERN_DEBUG "usbdev_open: Auto-resume failed.\n");
goto out_unlock_device;
+ }
ps->dev = dev;
ps->file = file;
@@ -1999,11 +2014,21 @@ static int usb_classdev_add(struct usb_device *dev)
{
struct device *cldev;
+ printk(KERN_DEBUG "Attempting to create file for usb bus %i dev %i,"
+ "minor = %i, major = %i\n",
+ dev->bus->busnum, dev->devnum,
+ MAJOR(dev->dev.devt),
+ MINOR(dev->dev.devt));
cldev = device_create(usb_classdev_class, &dev->dev, dev->dev.devt,
NULL, "usbdev%d.%d", dev->bus->busnum,
dev->devnum);
if (IS_ERR(cldev))
return PTR_ERR(cldev);
+ printk(KERN_DEBUG "Created file for usb bus %i dev %i,"
+ "minor = %i, major = %i\n",
+ dev->bus->busnum, dev->devnum,
+ MAJOR(dev->dev.devt),
+ MINOR(dev->dev.devt));
dev->usb_classdev = cldev;
return 0;
}
--
1.6.3.3
