Aug 11 07:49:05 artus kernel: hub.c: port 2, portstatus 503, change 10, 480 Mb/s
Aug 11 07:49:05 artus kernel: hub.c: new USB device 00:02.2-2, assigned address 4
Aug 11 07:49:05 artus kernel: usb.c: kmalloc IF deeb3400, numif 1
Aug 11 07:49:05 artus kernel: usb.c: new device strings: Mfr=0, Product=1, SerialNumber=0
Aug 11 07:49:05 artus kernel: usb.c: USB device number 4 default language ID 0x409
Aug 11 07:49:05 artus kernel: Product: USB TO IDE
Looking like one of the currently-problematic GeneSys adapters...
Aug 11 07:49:05 artus kernel: scsi1 : SCSI emulation for USB Mass Storage devices
Aug 11 07:49:05 artus kernel: Vendor: Maxtor 6 Model: Y120L0 Rev: 0811
Aug 11 07:49:05 artus kernel: Type: Direct-Access ANSI SCSI revision: 02
Aug 11 07:49:05 artus kernel: Attached scsi disk sda at scsi1, channel 0, id 0, lun 0
Aug 11 07:49:05 artus kernel: SCSI device sda: 240121728 512-byte hdwr sectors (122942 MB)
Aug 11 07:49:05 artus kernel: /dev/scsi/host1/bus0/target0/lun0: p1
Aug 11 07:49:05 artus kernel: WARNING: USB Mass Storage data integrity not assured
Aug 11 07:49:05 artus kernel: USB Mass Storage device found at 4
Aug 11 07:49:05 artus kernel: usb.c: usb-storage driver claimed interface deeb3400
...
All that was normal.
If I'm translating these bitmasks right, this 4KB ep2out-bulk transfer worked fine for three packets (512 bytes each) and then the device started to NAK every PING it was sent. Which caused a timeout.
Unclear why it stopped accepting more OUT data.
Aug 11 07:51:46 artus kernel: ehci_hcd 00:02.2: cancel qh dfe13100 n1fe13002 info 42002204 40000000 qtd 1fe120c0
Aug 11 07:51:46 artus kernel: ehci_hcd 00:02.2: overlay td dfe13110 n1fe12060 00000003 t8a008c81 p0=176e3600
Aug 11 07:51:46 artus kernel: ehci_hcd 00:02.2: cancel td dfe120c0 n1fe12060 00000001 t10008c80 p0=176e3000
Aug 11 07:51:51 artus kernel: usb_control/bulk_msg: timeout
This next one is going to ep0. Timeout on the status (IN) stage of some control OUT request ... but there's no message about timeout, which is curious. (Maybe it doesn't use usb_control_msg to clear the endpoint halts.)
Aug 11 07:51:51 artus kernel: ehci_hcd 00:02.2: cancel qh dfe13080 n1fe13002 info 40406004 40000000 qtd 1fe121e0
Aug 11 07:51:51 artus kernel: ehci_hcd 00:02.2: overlay td dfe13090 n1fe120c0 0000001f t80008d80 p0=00000000
Aug 11 07:51:51 artus kernel: ehci_hcd 00:02.2: cancel td dfe121e0 n1fe120c0 00000001 t80008d80 p0=00000000
This next one is ep2out-bulk again, with 0x01f (31) bytes timing out. No OUT packets are being accepted by this device, it's still reporting that it's NAKing all PING requests. So, timeout; but this is the normal route, as if from usb_bulk_msg.
Aug 11 07:52:01 artus kernel: ehci_hcd 00:02.2: cancel qh dfe13100 n1fe13002 info 42002204 40000000 qtd 1fe12060
Aug 11 07:52:01 artus kernel: ehci_hcd 00:02.2: overlay td dfe13110 n1fe12120 00000005 t801f8c81 p0=1eeb3740
Aug 11 07:52:01 artus kernel: ehci_hcd 00:02.2: cancel td dfe12060 n1fe12120 00000001 t001f8c80 p0=1eeb3740
Aug 11 07:52:06 artus kernel: usb_control/bulk_msg: timeout
Again timing out on the status stage (zero length) of some ep0 transfer, except this time status is OUT so it's a control-IN.
Aug 11 07:52:06 artus kernel: ehci_hcd 00:02.2: cancel qh dfe13080 n1fe13002 info 40406004 40000000 qtd 1fe121e0
Aug 11 07:52:06 artus kernel: ehci_hcd 00:02.2: overlay td dfe13090 n1fe12060 00000001 t80008d80 p0=00000000
Aug 11 07:52:06 artus kernel: ehci_hcd 00:02.2: cancel td dfe121e0 n1fe12060 00000001 t80008d80 p0=00000000
Aug 11 07:52:11 artus kernel: usb_control/bulk_msg: timeout
And again timing out on an ep0in status stage.
Aug 11 07:52:11 artus kernel: ehci_hcd 00:02.2: cancel qh dfe13080 n1fe13002 info 40406004 40000000 qtd 1fe121e0
Aug 11 07:52:11 artus kernel: ehci_hcd 00:02.2: overlay td dfe13090 n1fe120c0 00000005 t80008d80 p0=00000000
Aug 11 07:52:11 artus kernel: ehci_hcd 00:02.2: cancel td dfe121e0 n1fe120c0 00000001 t80008d80 p0=00000000
Then more wierdness happens right here. It's as if usb-storage decided to reset the port used by that device, and it came back as full speed instead of high speed ... that's odd at an electical level, not just in terms of "why did storage do that".
Which would jive with some sort of hardware problem in those "USB-to-IDE" adapters, as I've been suspecting since this round of problem reports started. Even if part of the problem here were to be a bug in ehci-hcd, I think this particular wierdness suggests hardware/firmware issues.
Aug 11 07:52:11 artus kernel: hub.c: port 2, portstatus 511, change 0, 480 Mb/s
Aug 11 07:52:11 artus kernel: hub.c: port 2 of hub 1 not reset yet, waiting 10ms
Aug 11 07:52:11 artus kernel: hub.c: port 2, portstatus 511, change 0, 480 Mb/s
Aug 11 07:52:11 artus kernel: hub.c: port 2 of hub 1 not reset yet, waiting 10ms
Aug 11 07:52:11 artus kernel: ehci_hcd 00:02.2: port 2 full speed --> companion
Aug 11 07:52:11 artus kernel: ehci_hcd 00:02.2: GetStatus port 2 status 003001 POWER OWNER sig=se0 CONNECT
Aug 11 07:52:11 artus kernel: hub.c: port 2, portstatus 0, change 10, 12 Mb/s
Aug 11 07:52:11 artus kernel: ehci_hcd 00:02.2: GetStatus port 1 status 003802 POWER OWNER sig=j CSC
Aug 11 07:52:11 artus kernel: hub.c: port 1, portstatus 0, change 1, 12 Mb/s
Aug 11 07:52:11 artus kernel: hub.c: port 1 connection change
Aug 11 07:52:11 artus kernel: hub.c: port 1, portstatus 0, change 1, 12 Mb/s
Aug 11 07:52:11 artus kernel: ehci_hcd 00:02.2: GetStatus port 2 status 001002 POWER sig=se0 CSC
Aug 11 07:52:11 artus kernel: hub.c: port 2, portstatus 100, change 1, 12 Mb/s
Aug 11 07:52:11 artus kernel: hub.c: port 2 connection change
Aug 11 07:52:11 artus kernel: hub.c: port 2, portstatus 100, change 1, 12 Mb/s
Aug 11 07:52:11 artus kernel: usb.c: USB disconnect on device 00:02.2-2 address 4
Aug 11 07:52:11 artus kernel: ehci_hcd 00:02.2: free_config 2 devnum 4
At this point, the device is no longer available to USB drivers, modulo some structural problems in 2.4 USB code (it has to trust drivers to behave in disconnect processing, many don't; so faults can be trouble).
Aug 11 07:52:11 artus kernel: hub.c: port 3, portstatus 100, change 0, 12 Mb/s
Aug 11 07:52:11 artus kernel: hub.c: port 4, portstatus 100, change 0, 12 Mb/s
Aug 11 07:52:11 artus kernel: hub.c: port 5, portstatus 100, change 0, 12 Mb/s
Aug 11 07:52:11 artus kernel: hub.c: port 6, portstatus 100, change 0, 12 Mb/s
Aug 11 07:52:16 artus kernel: usb-storage: host_reset() requested but not implemented
Aug 11 07:52:26 artus kernel: scsi: device set offline - command error recover failed: host 1 channel 0 id 0 lun 0
Aug 11 07:52:26 artus kernel: 248
Aug 11 07:52:26 artus kernel: I/O error: dev 08:01, sector 88989496
Aug 11 07:52:26 artus kernel: I/O error: dev 08:01, sector 88989744
The SCSI layer failed about 45 seconds after the first timeout, and 15 seconds after the device disconnected itself.
Thanks for this more detailed kernel log information. The diagnostics in that patch really do suggest hardware flakiness to me -- assuming that I interpreted those bit patterns correctly. You wouldn't be able to do anything like watch usb traffic on a CATC would you?
What's odd is that you report older code working better with this particular hardware. Nothing here suggests driver bugs. So I'm wondering if the difference is that 2.4.22 code talks faster to that hardware, which doesn't like that.
As an experiment, try modifying "ehci-hcd.c". There's a line in ehci_start() that masks a register value with 0x0fff (that constant only lives in that one place). In 2.4.22 that changed, so the 0x0f00 bits were preserved ... speeding up NForce2 by leaving the "park" mode enabled.
Try making that mask be 0x00ff, disabling "park" so the host won't try three consecutive OUT packets. If that helps, please also try 0x0aff, which still gets some speed improvements from the "park" mode but won't push double-buffered devices as hard.
- Dave
------------------------------------------------------- This SF.Net email sponsored by: Free pre-built ASP.NET sites including Data Reports, E-commerce, Portals, and Forums are available now. Download today and enter to win an XBOX or Visual Studio .NET. http://aspnet.click-url.com/go/psa00100003ave/direct;at.aspnet_072303_01/01 _______________________________________________ [EMAIL PROTECTED] To unsubscribe, use the last form field at: https://lists.sourceforge.net/lists/listinfo/linux-usb-devel
