On Wed, 17 Mar 2004, Matthias Andree wrote:
> > I looked at your logs. Interestingly, the problems occur with control
> > transfers, not bulk transfers, but the strace only shows USBDEVFS_BULK
> > ioctls, not USBDEVFS_CONTROL. I can't imagine what that means or how it
> > happened. (Unless it's a bug in strace?)
>
> I wouldn't bet on strace being up to date.
Another possibility (should have thought of this before) is that the
control transfers come from a different process, maybe a child of the one
you're tracing. Not that it really matters...
> I tried it on 2.4.26-pre4 (current BitKeeper), it failed:
>
> devio.c: In function `proc_control':
> devio.c:563: error: structure has no member named `bRequestType'
> devio.c:563: error: structure has no member named `bRequest'
> devio.c:563: error: structure has no member named `wValue'
> devio.c:563: error: structure has no member named `wIndex'
> devio.c:564: error: structure has no member named `wLength'
> make[3]: *** [devio.o] Fehler 1
Whoops. Some field entries got renamed during the 2.5 kernel run; I had
forgotten.
> So we have 2.6 logs with your patch for now.
>
> One thing that is a bit strange is the excessive hotplug action just
> through starting an application. Whatever that's good for...
I think the program opens and closes the scanner device file several
times, and each time it configures the device that generates a hotplug
event. Don't worry about it.
> The 2.6 log is, with date and host name stripped and driver core
> debugging enabled:
Never mind the details here. It's a little difficult to match up entries
in the log; it looks like there are overlapping requests. The new patches
will make things clearer.
They also will print out the timeout values in the control requests; it
seems clear that the requests have timeouts that are much too short.
This could easily confuse the scanner -- sending a new request out to
the scanner before it has finished processing the old one.
Attached are versions of the patch for both 2.6 and 2.4. It will be
interesting to compare the results.
Alan Stern
===== drivers/usb/core/devio.c 1.87 vs edited =====
--- 2.6.4/drivers/usb/core/devio.c Mon Mar 1 06:40:11 2004
+++ edited/drivers/usb/core/devio.c Wed Mar 17 13:52:35 2004
@@ -539,6 +539,8 @@
unsigned int tmo;
unsigned char *tbuf;
int i, ret;
+ static int counter;
+ int cnt;
if (copy_from_user(&ctrl, arg, sizeof(ctrl)))
return -EFAULT;
@@ -549,6 +551,11 @@
if (!(tbuf = (unsigned char *)__get_free_page(GFP_KERNEL)))
return -ENOMEM;
tmo = (ctrl.timeout * HZ + 999) / 1000;
+ cnt = ++counter;
+ printk(KERN_DEBUG "usbfs: proc_control: dev %d cnt %d tmo %d "
+ "rqt %x rq %x val %x ind %x len %u\n",
+ dev->devnum, cnt, ctrl.timeout, ctrl.bRequestType,
+ ctrl.bRequest, ctrl.wValue, ctrl.wIndex, ctrl.wLength);
if (ctrl.bRequestType & 0x80) {
if (ctrl.wLength && !access_ok(VERIFY_WRITE, ctrl.data, ctrl.wLength))
{
free_page((unsigned long)tbuf);
@@ -573,6 +580,7 @@
ctrl.wValue, ctrl.wIndex, tbuf, ctrl.wLength,
tmo);
}
free_page((unsigned long)tbuf);
+ printk(KERN_DEBUG "usbfs: proc_control: cnt %d result %d\n", cnt, i);
if (i<0) {
printk(KERN_DEBUG "usbfs: USBDEVFS_CONTROL failed "
"cmd %s dev %d rqt %u rq %u len %u ret %d\n",
--- 2.2.24/drivers/usb/devio.c Mon Mar 1 06:40:11 2004
+++ edited/drivers/usb/devio.c Wed Mar 17 13:52:35 2004
@@ -549,6 +549,8 @@
unsigned int tmo;
unsigned char *tbuf;
int i, ret;
+ static int counter;
+ int cnt;
if (copy_from_user(&ctrl, (void *)arg, sizeof(ctrl)))
return -EFAULT;
@@ -559,6 +561,11 @@
if (!(tbuf = (unsigned char *)__get_free_page(GFP_KERNEL)))
return -ENOMEM;
tmo = (ctrl.timeout * HZ + 999) / 1000;
+ cnt = ++counter;
+ printk(KERN_DEBUG "usbfs: proc_control: dev %d cnt %d tmo %d "
+ "rqt %x rq %x val %x ind %x len %u\n",
+ dev->devnum, cnt, ctrl.timeout, ctrl.requesttype,
+ ctrl.request, ctrl.value, ctrl.index, ctrl.length);
if (ctrl.requesttype & 0x80) {
if (ctrl.length && !access_ok(VERIFY_WRITE, ctrl.data, ctrl.length)) {
free_page((unsigned long)tbuf);
@@ -583,6 +590,7 @@
ctrl.value, ctrl.index, tbuf, ctrl.length, tmo);
}
free_page((unsigned long)tbuf);
+ printk(KERN_DEBUG "usbfs: proc_control: cnt %d result %d\n", cnt, i);
if (i<0) {
printk(KERN_DEBUG "usbdevfs: USBDEVFS_CONTROL failed dev %d rqt %u rq
%u len %u ret %d\n",
dev->devnum, ctrl.requesttype, ctrl.request, ctrl.length, i);
