2009-11-13 23:04:16

by Alexander Holler

[permalink] [raw]
Subject: Problems with p55-express and sleeping usb-hds

Hello,

I'm having a problem with kernels (x86_64) <=2.6.32-rc7 (that means all
kernels I tried, including the latest stable 2.6.31.6) on a Gigabyte
P55M-UD4 mb (Bios F4l) with an Intel Core i7 860 and sleeping usb-hds.

I don't have the problems when using the same usb-drives on a laptop
with a core2duo (ICH8), so it seems to be a problem with the chipset
(p55-express).

The problem seems to occur when the usb-drive goes to sleep (because of
inactivity) and the kernel tries to access them afterwards.

Here are the excerpts from the log:

-------------------------------------------------------------------------
Nov 13 19:03:34 krabat kernel: [ 0.000000] Linux version 2.6.32-rc7
([email protected]) (gcc version 4.4.1 20090725 (Red Hat 4.4.1-2)
(GCC) ) #1 SMP Fri Nov 13 19:01:02 CET 2009

...

(This warning seems to be unrelated, but I'm getting this too with every
kernel I've tried, so I'm including it here)

Nov 13 19:03:34 krabat kernel: [ 1.259269] cpuidle: using governor menu
Nov 13 19:03:34 krabat kernel: [ 1.259274] ------------[ cut here
]------------
Nov 13 19:03:34 krabat kernel: [ 1.259278] WARNING: at
arch/x86/kernel/hpet.c:390 hpet_next_event+0x68/0x80()
Nov 13 19:03:34 krabat kernel: [ 1.259279] Hardware name: P55M-UD4
Nov 13 19:03:34 krabat kernel: [ 1.259280] Modules linked in:
Nov 13 19:03:34 krabat kernel: [ 1.259282] Pid: 0, comm: swapper Not
tainted 2.6.32-rc7 #1
Nov 13 19:03:34 krabat kernel: [ 1.259283] Call Trace:
Nov 13 19:03:34 krabat kernel: [ 1.259287] [<ffffffff8103b0a3>] ?
warn_slowpath_common+0x73/0xb0
Nov 13 19:03:34 krabat kernel: [ 1.259289] [<ffffffff81025648>] ?
hpet_next_event+0x68/0x80
Nov 13 19:03:34 krabat kernel: [ 1.259292] [<ffffffff8105de28>] ?
tick_dev_program_event+0x38/0xc0
Nov 13 19:03:34 krabat kernel: [ 1.259293] [<ffffffff8105d7cd>] ?
tick_broadcast_oneshot_control+0x10d/0x110
Nov 13 19:03:34 krabat kernel: [ 1.259295] [<ffffffff8105d05d>] ?
tick_notify+0x31d/0x440
Nov 13 19:03:34 krabat kernel: [ 1.259298] [<ffffffff81055a37>] ?
notifier_call_chain+0x37/0x70
Nov 13 19:03:34 krabat kernel: [ 1.259299] [<ffffffff8105c86b>] ?
clockevents_notify+0x2b/0x90
Nov 13 19:03:34 krabat kernel: [ 1.259303] [<ffffffff812086b2>] ?
acpi_idle_enter_bm+0x15e/0x2cc
Nov 13 19:03:34 krabat kernel: [ 1.259306] [<ffffffff8129727b>] ?
cpuidle_idle_call+0x9b/0x110
Nov 13 19:03:34 krabat kernel: [ 1.259308] [<ffffffff8100a4dc>] ?
cpu_idle+0x5c/0xb0
Nov 13 19:03:34 krabat kernel: [ 1.259312] ---[ end trace
a8b94b9411d73a80 ]---

...

(Here I have plugged in one of those discs)

Nov 13 19:04:07 krabat kernel: [ 55.344953] usb 9-7: new high speed
USB device using ehci_hcd and address 3
Nov 13 19:04:07 krabat kernel: [ 55.491513] usb 9-7: New USB device
found, idVendor=0bc2, idProduct=2100
Nov 13 19:04:07 krabat kernel: [ 55.491517] usb 9-7: New USB device
strings: Mfr=1, Product=2, SerialNumber=3
Nov 13 19:04:07 krabat kernel: [ 55.491521] usb 9-7: Product: FreeAgent Go
Nov 13 19:04:07 krabat kernel: [ 55.491523] usb 9-7: Manufacturer: Seagate
Nov 13 19:04:07 krabat kernel: [ 55.491525] usb 9-7: SerialNumber:
2GE1IXJ9
Nov 13 19:04:07 krabat kernel: [ 55.491661] usb 9-7: configuration #1
chosen from 1 choice
Nov 13 19:04:07 krabat kernel: [ 55.544762] Initializing USB Mass
Storage driver...
Nov 13 19:04:07 krabat kernel: [ 55.545011] scsi6 : SCSI emulation for
USB Mass Storage devices
Nov 13 19:04:07 krabat kernel: [ 55.545348] usbcore: registered new
interface driver usb-storage
Nov 13 19:04:07 krabat kernel: [ 55.545520] USB Mass Storage support
registered.
Nov 13 19:04:12 krabat kernel: [ 60.533824] scsi 6:0:0:0:
Direct-Access Seagate FreeAgent Go 102D PQ: 0 ANSI: 4
Nov 13 19:04:12 krabat kernel: [ 60.534036] sd 6:0:0:0: Attached scsi
generic sg1 type 0
Nov 13 19:04:12 krabat kernel: [ 60.535901] sd 6:0:0:0: [sdb]
976773168 512-byte logical blocks: (500 GB/465 GiB)
Nov 13 19:04:12 krabat kernel: [ 60.537208] sd 6:0:0:0: [sdb] Write
Protect is off
Nov 13 19:04:12 krabat kernel: [ 60.537216] sd 6:0:0:0: [sdb] Assuming
drive cache: write through
Nov 13 19:04:12 krabat kernel: [ 60.540517] sd 6:0:0:0: [sdb] Assuming
drive cache: write through
Nov 13 19:04:12 krabat kernel: [ 60.540521] sdb:
Nov 13 19:04:12 krabat kernel: [ 60.778284] sdb1 sdb2 sdb3
Nov 13 19:04:12 krabat kernel: [ 60.781552] sd 6:0:0:0: [sdb] Assuming
drive cache: write through
Nov 13 19:04:12 krabat kernel: [ 60.781557] sd 6:0:0:0: [sdb] Attached
SCSI disk

...

(And here comes the problem)

Nov 13 19:47:34 krabat kernel: [ 2655.981980] usb 9-7: reset high speed
USB device using ehci_hcd and address 3
Nov 13 19:47:39 krabat kernel: [ 2661.120397] usb 9-7: device firmware
changed
Nov 13 19:47:39 krabat kernel: [ 2661.120489] usb 9-7: USB disconnect,
address 3
Nov 13 19:47:39 krabat kernel: [ 2661.120521] sd 6:0:0:0: Device
offlined - not ready after error recovery
Nov 13 19:47:39 krabat kernel: [ 2661.120528] sd 6:0:0:0: [sdb]
Unhandled error code
Nov 13 19:47:39 krabat kernel: [ 2661.120531] sd 6:0:0:0: [sdb] Result:
hostbyte=DID_ABORT driverbyte=DRIVER_OK
Nov 13 19:47:39 krabat kernel: [ 2661.120536] sd 6:0:0:0: [sdb] CDB:
Read(10): 28 00 03 04 7b da 00 00 10 00
Nov 13 19:47:39 krabat kernel: [ 2661.120546] end_request: I/O error,
dev sdb, sector 50625498
Nov 13 19:47:39 krabat kernel: [ 2661.120555] sd 6:0:0:0: rejecting I/O
to offline device
Nov 13 19:47:39 krabat kernel: [ 2661.120584] sd 6:0:0:0: [sdb]
Unhandled error code
Nov 13 19:47:39 krabat kernel: [ 2661.120587] sd 6:0:0:0: [sdb] Result:
hostbyte=DID_NO_CONNECT driverbyte=DRIVER_OK
Nov 13 19:47:39 krabat kernel: [ 2661.120593] sd 6:0:0:0: [sdb] CDB:
Read(10): 28 00 03 04 7b ea 00 00 f0 00
Nov 13 19:47:39 krabat kernel: [ 2661.120641] end_request: I/O error,
dev sdb, sector 50625514
Nov 13 19:47:40 krabat kernel: [ 2661.371696] usb 9-7: new high speed
USB device using ehci_hcd and address 5
Nov 13 19:47:41 krabat kernel: [ 2662.329564] EXT4-fs error (device
dm-0): __ext4_get_inode_loc: unable to read inode block - inode=3250,
block=1260
Nov 13 19:47:43 krabat kernel: [ 2664.658446] EXT4-fs error (device
dm-0): __ext4_get_inode_loc: unable to read inode block - inode=7078109,
block=28311597
Nov 13 19:47:44 krabat kernel: [ 2665.259794] __ratelimit: 126 callbacks
suppressed
...
-------------------------------------------------------------------------

If someone needs a full log, logs with some debugging options turned on,
or has some patches for me to test, just send me a mail.

Kind regards,

Alexander Holler


2009-11-13 23:27:29

by Robert Hancock

[permalink] [raw]
Subject: Re: Problems with p55-express and sleeping usb-hds

On 11/13/2009 04:30 PM, Alexander Holler wrote:
> Hello,
>
> I'm having a problem with kernels (x86_64) <=2.6.32-rc7 (that means all
> kernels I tried, including the latest stable 2.6.31.6) on a Gigabyte
> P55M-UD4 mb (Bios F4l) with an Intel Core i7 860 and sleeping usb-hds.
>
> I don't have the problems when using the same usb-drives on a laptop
> with a core2duo (ICH8), so it seems to be a problem with the chipset
> (p55-express).
>
> The problem seems to occur when the usb-drive goes to sleep (because of
> inactivity) and the kernel tries to access them afterwards.
>
> Here are the excerpts from the log:
>
> ...
>
> (And here comes the problem)>
> Nov 13 19:47:34 krabat kernel: [ 2655.981980] usb 9-7: reset high speed
> USB device using ehci_hcd and address 3
> Nov 13 19:47:39 krabat kernel: [ 2661.120397] usb 9-7: device firmware
> changed
> Nov 13 19:47:39 krabat kernel: [ 2661.120489] usb 9-7: USB disconnect,
> address 3

That sounds like the device started reporting a different firmware
string after it woke up, and the kernel decided it wasn't the same
device anymore and triggered a disconnect/reconnect..

2009-11-13 23:28:03

by Oliver Neukum

[permalink] [raw]
Subject: Re: Problems with p55-express and sleeping usb-hds

Am Freitag, 13. November 2009 23:30:14 schrieb Alexander Holler:
> (And here comes the problem)
>
> Nov 13 19:47:34 krabat kernel: [ 2655.981980] usb 9-7: reset high speed
> USB device using ehci_hcd and address 3
> Nov 13 19:47:39 krabat kernel: [ 2661.120397] usb 9-7: device firmware
> changed

You cut too early. This shows a failed reset but not the cause.

Regards
Oliver

2009-11-13 23:35:41

by Alexander Holler

[permalink] [raw]
Subject: Re: Problems with p55-express and sleeping usb-hds

Am 14.11.2009 00:30, schrieb Oliver Neukum:
> Am Freitag, 13. November 2009 23:30:14 schrieb Alexander Holler:
>> (And here comes the problem)
>>
>> Nov 13 19:47:34 krabat kernel: [ 2655.981980] usb 9-7: reset high speed
>> USB device using ehci_hcd and address 3
>> Nov 13 19:47:39 krabat kernel: [ 2661.120397] usb 9-7: device firmware
>> changed
>
> You cut too early. This shows a failed reset but not the cause.

There are no relevant messages in the log before:

--------
Nov 13 19:06:23 krabat kernel: [ 190.790549] EXT4-fs (dm-1): mounted
filesystem with ordered data mode
Nov 13 19:08:05 krabat ntpd[3381]: synchronized to 192.168.207.1,
stratum 2
Nov 13 19:08:05 krabat ntpd[3381]: kernel time sync status change 2001

Nov 13 19:47:34 krabat kernel: [ 2655.981980] usb 9-7: reset high speed
USB device using ehci_hcd and address 3
----------------------------------------------------

2009-11-14 02:03:01

by Alexander Holler

[permalink] [raw]
Subject: Re: Problems with p55-express and sleeping usb-hds

Am 14.11.2009 00:27, schrieb Robert Hancock:
>> (And here comes the problem)>
>> Nov 13 19:47:34 krabat kernel: [ 2655.981980] usb 9-7: reset high speed
>> USB device using ehci_hcd and address 3
>> Nov 13 19:47:39 krabat kernel: [ 2661.120397] usb 9-7: device firmware
>> changed
>> Nov 13 19:47:39 krabat kernel: [ 2661.120489] usb 9-7: USB disconnect,
>> address 3
>
> That sounds like the device started reporting a different firmware
> string after it woke up, and the kernel decided it wasn't the same
> device anymore and triggered a disconnect/reconnect..
> --

I don't think it's a problem with the devices. I'm using them (more than
1) for some months now and never have had any problems. The problem
first started, when I've switched to the box with the p55-express and I
still don't have any problems with these devices on other machines.

Kind regards,

Alexander Holler

2009-11-14 02:32:24

by Matthew Garrett

[permalink] [raw]
Subject: Re: Problems with p55-express and sleeping usb-hds

http://www.engadget.com/2009/10/31/iphone-and-windows-7-dont-play-nice-intel-p55-chipset-to-blame/
and similar stories elsewhere - some systems seem to have received BIOS
updates that deal with the issue. It'd be nice to know what those
updates do.

--
Matthew Garrett | [email protected]

2009-11-14 02:51:00

by Alexander Holler

[permalink] [raw]
Subject: Re: Problems with p55-express and sleeping usb-hds

Hello,

Am 14.11.2009 00:35, schrieb Alexander Holler:
> Am 14.11.2009 00:30, schrieb Oliver Neukum:
>> Am Freitag, 13. November 2009 23:30:14 schrieb Alexander Holler:
>>> (And here comes the problem)
>>>
>>> Nov 13 19:47:34 krabat kernel: [ 2655.981980] usb 9-7: reset high speed
>>> USB device using ehci_hcd and address 3
>>> Nov 13 19:47:39 krabat kernel: [ 2661.120397] usb 9-7: device firmware
>>> changed
>>
>> You cut too early. This shows a failed reset but not the cause.
>
> There are no relevant messages in the log before:
>
> --------
> Nov 13 19:06:23 krabat kernel: [ 190.790549] EXT4-fs (dm-1): mounted
> filesystem with ordered data mode
> Nov 13 19:08:05 krabat ntpd[3381]: synchronized to 192.168.207.1, stratum 2
> Nov 13 19:08:05 krabat ntpd[3381]: kernel time sync status change 2001
> Nov 13 19:47:34 krabat kernel: [ 2655.981980] usb 9-7: reset high speed
> USB device using ehci_hcd and address 3
> ----------------------------------------------------

it might be that my assumption is totally wrong an the usb-disconnect is
unrelated to the time the usb-drives are going to sleep. What I have
done inbetween that mount and the disconnect was a rsync -c -n (dry-run)
between two of those usb-discs (I'm using them for backups). Both drives
are containing the same files, some large (up to 5-10 gb) and small
files. Looking at the leds of those usb-drives I just assumed the
problem happens when one of those was inactive for some time (because
rsync computes the hash of one of the large files on the other drive).
In the excerpt of the log I've posted before, I've cut out the
disconnect of the other drive, which has happend almost at the same time
(and with the same consequences) as the one shown. In fact I've cut out
one line from the log (sorry for that):
---------
Nov 13 19:08:05 krabat ntpd[3381]: kernel time sync status change 2001
Nov 13 19:47:34 krabat kernel: [ 2655.981980] usb 9-7: reset high speed
USB device using ehci_hcd and address 3
Nov 13 19:47:35 krabat kernel: [ 2656.233278] usb 9-1: reset high speed
USB device using ehci_hcd and address 4
Nov 13 19:47:39 krabat kernel: [ 2661.120397] usb 9-7: device firmware
changed
Nov 13 19:47:39 krabat kernel: [ 2661.120489] usb 9-7: USB disconnect,
address 3
---------
Afterwards the messages for the second drive where the same as for the
one I've posted.

This is reproducible, at least through starting the rsync. I will turn
on some debugging knobs and will see if I can see some more hints in the
resulting logs.

Kind regards,

Alexander Holler

2009-11-14 10:04:20

by Oliver Neukum

[permalink] [raw]
Subject: Re: Problems with p55-express and sleeping usb-hds

Am Samstag, 14. November 2009 03:50:53 schrieb Alexander Holler:
> In the excerpt of the log I've posted before, I've cut out the
> disconnect of the other drive, which has happend almost at the same time
> (and with the same consequences) as the one shown. In fact I've cut out
> one line from the log (sorry for that):
> ---------
> Nov 13 19:08:05 krabat ntpd[3381]: kernel time sync status change 2001
> Nov 13 19:47:34 krabat kernel: [ 2655.981980] usb 9-7: reset high speed
> USB device using ehci_hcd and address 3

Reset.

> Nov 13 19:47:35 krabat kernel: [ 2656.233278] usb 9-1: reset high speed
> USB device using ehci_hcd and address 4
> Nov 13 19:47:39 krabat kernel: [ 2661.120397] usb 9-7: device firmware
> changed

Descriptors changed

> Nov 13 19:47:39 krabat kernel: [ 2661.120489] usb 9-7: USB disconnect,
> address 3

Forced unbind

> ---------
> Afterwards the messages for the second drive where the same as for the
> one I've posted.
>
> This is reproducible, at least through starting the rsync. I will turn
> on some debugging knobs and will see if I can see some more hints in the
> resulting logs.

You can recompile with CONFIG_USB_DEBUG and CONFIG_USB_STORAGE_DEBUG.

Regards
Oliver

2009-11-14 17:31:51

by Alexander Holler

[permalink] [raw]
Subject: Re: Problems with p55-express and sleeping usb-hds

Hello,

Am 14.11.2009 11:06, schrieb Oliver Neukum:
> You can recompile with CONFIG_USB_DEBUG and CONFIG_USB_STORAGE_DEBUG.

Here it comes. I've used 2.6.31.6 and turned usb-(storage-)debug on.
After mounting the two large encrypted files (loop and dmcrypt) from the
two connected usb-drives, I've started the rsync -n to compare both
partitions:

--------------------------------
Nov 14 13:03:41 krabat kernel: [ 164.474820] EXT4-fs (dm-1): mounted
filesystem with ordered data mode
Nov 14 13:04:38 krabat kernel: [ 220.963256] 3c da 00 00 10 00
...
(many lines with hex-numbers, nothing else)
...
Nov 14 14:18:49 krabat kernel: [ 4672.953175] 28 00 04 e8 3d da 00 00
10 00
Nov 14 14:18:49 krabat kernel: [ 4672.960345] 00 f0 00

Nov 14 14:18:49 krabat kernel: [ 4672.966138] 00

Nov 14 14:18:50 krabat kernel: [ 4673.071643] 00 04 e8 50 da 00 00 10
00
Nov 14 14:18:50 krabat kernel: [ 4673.077825] 00

Nov 14 14:18:50 krabat kernel: [ 4673.077833] 10 00

Nov 14 14:18:50 krabat kernel: [ 4673.336765] 00 f0 00

Nov 14 14:18:50 krabat kernel: [ 4673.342205] 28 00 05 3b 40 da 00 00
10 00
Nov 14 14:18:50 krabat kernel: [ 4673.342230] 00

Nov 14 14:18:50 krabat kernel: [ 4673.342235]

Nov 14 14:18:51 krabat kernel: [ 4674.647846] 28 00 05 3c 15 da 00 00
10 00
Nov 14 14:18:51 krabat kernel: [ 4674.822258]

Nov 14 14:18:51 krabat kernel: [ 4674.828338] 28 00 04 e9 6e ea 00 00
f0 00
Nov 14 14:18:57 krabat kernel: [ 4680.042678] 54 da 00 00 10 00

Nov 14 14:18:59 krabat kernel: [ 4682.646818] 00 05 e2 0c da 00 00 10
00
Nov 14 14:19:00 krabat kernel: [ 4683.516686] 00 f0 00

Nov 14 14:19:00 krabat kernel: [ 4683.522288] 28 00 05 e6 9f da 00 00
10 00
Nov 14 14:19:07 krabat kernel: [ 4690.760331]

Nov 14 14:19:39 krabat kernel: [ 4722.339214] usb 9-1: reset high speed
USB device using ehci_hcd and address 4
Nov 14 14:19:39 krabat kernel: [ 4722.591235] usb 9-7: reset high speed
USB device using ehci_hcd and address 3
Nov 14 14:19:44 krabat kernel: [ 4727.491664] usb 9-1: device firmware
changed
Nov 14 14:19:44 krabat kernel: [ 4727.491718] usb 9-1: USB disconnect,
address 4
Nov 14 14:19:44 krabat kernel: [ 4727.493060] scsi 7:0:0:0: Device
offlined - not ready after error recovery
Nov 14 14:19:44 krabat kernel: [ 4727.493069] scsi 7:0:0:0: [sdc]
Unhandled error code
Nov 14 14:19:44 krabat kernel: [ 4727.493072] scsi 7:0:0:0: [sdc]
Result: hostbyte=DID_ABORT driverbyte=DRIVER_OK
Nov 14 14:19:44 krabat kernel: [ 4727.493077] end_request: I/O error,
dev sdc, sector 317945322
Nov 14 14:19:44 krabat kernel: [ 4727.493091] scsi 7:0:0:0: rejecting
I/O to offline device
Nov 14 14:19:44 krabat kernel: [ 4727.493108] scsi 7:0:0:0: [sdc]
Unhandled error code
Nov 14 14:19:44 krabat kernel: [ 4727.493110] scsi 7:0:0:0: [sdc]
Result: hostbyte=DID_NO_CONNECT driverbyte=DRIVER_OK
Nov 14 14:19:44 krabat kernel: [ 4727.493114] end_request: I/O error,
dev sdc, sector 317945562
Nov 14 14:19:44 krabat kernel: [ 4727.615743] EXT4-fs error (device
dm-1): ext4_find_entry: reading directory #1771 offset 0
Nov 14 14:19:44 krabat kernel: [ 4727.616071] Buffer I/O error on device
dm-1, logical block 0
...
(many more io, buffer and ext4 errors)
...
--------------------------------

Regards,

Alexander

2009-11-17 00:19:38

by Alexander Holler

[permalink] [raw]
Subject: Re: Problems with p55-express and sleeping usb-hds

Hello,

Alexander Holler schrieb:
> ...
> (many lines with hex-numbers, nothing else)
> ...

shame on me. Sorry, I wasn't aware the logger (with default
configuration) of the system in question doesn't log every kernel
message. I've just started another rsync after I've changed that.

I useful log will follow after I reproduced the failure while logging
every kernel-message.

Regards,

Alexander

2009-11-17 00:52:50

by Alexander Holler

[permalink] [raw]
Subject: Re: Problems with p55-express and sleeping usb-hds

Hello,

Am 17.11.2009 01:19, schrieb Alexander Holler:
> shame on me. Sorry, I wasn't aware the logger (with default
> configuration) of the system in question doesn't log every kernel
> message. I've just started another rsync after I've changed that.

Here it is, I haven't cut anything in between and have choosen some
lines (of the 1gb-log I've got) before and after the first reset-message:

--------------------------------------------------
Nov 17 01:14:50 krabat kernel: [ 1219.910972] usb-storage: Bulk command
transfer result=0
Nov 17 01:14:50 krabat kernel: [ 1219.910975] usb-storage:
usb_stor_bulk_transfer_sglist: xfer 122880 bytes, 18 entries
Nov 17 01:14:50 krabat kernel: [ 1219.919173] ehci_hcd 0000:00:1d.7:
port 1 high speed
Nov 17 01:14:50 krabat kernel: [ 1219.919180] ehci_hcd 0000:00:1d.7:
GetStatus port 1 status 001005 POWER sig=se0 PE CONNECT
Nov 17 01:14:50 krabat kernel: [ 1219.937890] usb-storage: Status code
0; transferred 122880/122880
Nov 17 01:14:50 krabat kernel: [ 1219.937893] usb-storage: -- transfer
complete
Nov 17 01:14:50 krabat kernel: [ 1219.937896] usb-storage: Bulk data
transfer result 0x0
Nov 17 01:14:50 krabat kernel: [ 1219.937898] usb-storage: Attempting to
get CSW...
Nov 17 01:14:50 krabat kernel: [ 1219.937900] usb-storage:
usb_stor_bulk_transfer_buf: xfer 13 bytes
Nov 17 01:14:55 krabat kernel: [ 1224.973594] usb 3-1: usb-storage timed
out on ep0out len=0/0
Nov 17 01:14:55 krabat kernel: [ 1224.973718] usb-storage: Status code
0; transferred 13/13
Nov 17 01:14:55 krabat kernel: [ 1224.973721] usb-storage: -- transfer
complete
Nov 17 01:14:55 krabat kernel: [ 1224.973723] usb-storage: Bulk status
result = 0
Nov 17 01:14:55 krabat kernel: [ 1224.973726] usb-storage: Bulk Status S
0x53425355 T 0x72e1e R 0 Stat 0x0
Nov 17 01:14:55 krabat kernel: [ 1224.973729] usb-storage: scsi cmd
done, result=0x0
Nov 17 01:14:55 krabat kernel: [ 1224.973733] usb-storage: *** thread
sleeping.
Nov 17 01:14:55 krabat kernel: [ 1224.973753] usb-storage: queuecommand
called
Nov 17 01:14:55 krabat kernel: [ 1224.973766] usb-storage: *** thread
awakened.
Nov 17 01:14:55 krabat kernel: [ 1224.973770] usb-storage: Command
READ_10 (10 bytes)
Nov 17 01:14:55 krabat kernel: [ 1224.973772] usb-storage: 28 00 20 c5
40 da 00 00 10 00
Nov 17 01:14:55 krabat kernel: [ 1224.973785] usb-storage: Bulk Command
S 0x43425355 T 0x72e1f L 8192 F 128 Trg 0 LUN 0 CL 10
Nov 17 01:14:55 krabat kernel: [ 1224.973790] usb-storage:
usb_stor_bulk_transfer_buf: xfer 31 bytes
Nov 17 01:14:55 krabat kernel: [ 1224.997517] usb-storage: Status code
0; transferred 31/31
Nov 17 01:14:55 krabat kernel: [ 1224.997520] usb-storage: -- transfer
complete
Nov 17 01:14:55 krabat kernel: [ 1224.997522] usb-storage: Bulk command
transfer result=0
Nov 17 01:14:55 krabat kernel: [ 1224.997525] usb-storage:
usb_stor_bulk_transfer_sglist: xfer 8192 bytes, 2 entries
Nov 17 01:14:55 krabat kernel: [ 1225.021720] usb-storage: Status code
0; transferred 8192/8192
Nov 17 01:14:55 krabat kernel: [ 1225.021722] usb-storage: -- transfer
complete
Nov 17 01:14:55 krabat kernel: [ 1225.021725] usb-storage: Bulk data
transfer result 0x0
Nov 17 01:14:55 krabat kernel: [ 1225.021727] usb-storage: Attempting to
get CSW...
Nov 17 01:14:55 krabat kernel: [ 1225.021729] usb-storage:
usb_stor_bulk_transfer_buf: xfer 13 bytes
Nov 17 01:15:00 krabat kernel: [ 1230.175844] usb 3-1: usb-storage timed
out on ep0out len=0/0
Nov 17 01:15:00 krabat kernel: [ 1230.175958] usb-storage: Status code
0; transferred 13/13
Nov 17 01:15:00 krabat kernel: [ 1230.175961] usb-storage: -- transfer
complete
Nov 17 01:15:00 krabat kernel: [ 1230.175963] usb-storage: Bulk status
result = 0
Nov 17 01:15:00 krabat kernel: [ 1230.175966] usb-storage: Bulk Status S
0x53425355 T 0x72e1f R 0 Stat 0x0
Nov 17 01:15:00 krabat kernel: [ 1230.175969] usb-storage: scsi cmd
done, result=0x0
Nov 17 01:15:00 krabat kernel: [ 1230.175973] usb-storage: *** thread
sleeping.
Nov 17 01:15:00 krabat kernel: [ 1230.175990] usb-storage: queuecommand
called
Nov 17 01:15:00 krabat kernel: [ 1230.176001] usb-storage: *** thread
awakened.
Nov 17 01:15:00 krabat kernel: [ 1230.176006] usb-storage: Command
READ_10 (10 bytes)
Nov 17 01:15:00 krabat kernel: [ 1230.176009] usb-storage: 28 00 20 c5
40 ea 00 00 f0 00
Nov 17 01:15:00 krabat kernel: [ 1230.176021] usb-storage: Bulk Command
S 0x43425355 T 0x72e20 L 122880 F 128 Trg 0 LUN 0 CL 10
Nov 17 01:15:00 krabat kernel: [ 1230.176026] usb-storage:
usb_stor_bulk_transfer_buf: xfer 31 bytes
Nov 17 01:15:00 krabat kernel: [ 1230.199896] usb-storage: Status code
0; transferred 31/31
Nov 17 01:15:00 krabat kernel: [ 1230.199899] usb-storage: -- transfer
complete
Nov 17 01:15:00 krabat kernel: [ 1230.199901] usb-storage: Bulk command
transfer result=0
Nov 17 01:15:00 krabat kernel: [ 1230.199904] usb-storage:
usb_stor_bulk_transfer_sglist: xfer 122880 bytes, 14 entries
Nov 17 01:15:00 krabat kernel: [ 1230.226621] usb-storage: Status code
0; transferred 122880/122880
Nov 17 01:15:00 krabat kernel: [ 1230.226624] usb-storage: -- transfer
complete
Nov 17 01:15:00 krabat kernel: [ 1230.226627] usb-storage: Bulk data
transfer result 0x0
Nov 17 01:15:00 krabat kernel: [ 1230.226629] usb-storage: Attempting to
get CSW...
Nov 17 01:15:00 krabat kernel: [ 1230.226631] usb-storage:
usb_stor_bulk_transfer_buf: xfer 13 bytes
Nov 17 01:15:01 krabat kernel: [ 1230.379301] usb 3-1: device not
accepting address 4, error -110
Nov 17 01:15:01 krabat kernel: [ 1230.435354] ehci_hcd 0000:00:1d.7:
port 1 high speed
Nov 17 01:15:01 krabat kernel: [ 1230.435361] ehci_hcd 0000:00:1d.7:
GetStatus port 1 status 001005 POWER sig=se0 PE CONNECT
Nov 17 01:15:01 krabat kernel: [ 1230.491016] usb 3-1: reset high speed
USB device using ehci_hcd and address 4
Nov 17 01:15:06 krabat kernel: [ 1235.489802] usb 3-1: usb-storage timed
out on ep0in len=0/64
Nov 17 01:15:06 krabat kernel: [ 1235.489907] usb-storage: Status code
0; transferred 13/13
Nov 17 01:15:06 krabat kernel: [ 1235.489909] usb-storage: -- transfer
complete
Nov 17 01:15:06 krabat kernel: [ 1235.489912] usb-storage: Bulk status
result = 0
Nov 17 01:15:06 krabat kernel: [ 1235.489915] usb-storage: Bulk Status S
0x53425355 T 0x72e20 R 0 Stat 0x0
Nov 17 01:15:06 krabat kernel: [ 1235.489918] usb-storage: scsi cmd
done, result=0x0
Nov 17 01:15:06 krabat kernel: [ 1235.489922] usb-storage: *** thread
sleeping.
Nov 17 01:15:06 krabat kernel: [ 1235.489942] usb-storage: queuecommand
called
Nov 17 01:15:06 krabat kernel: [ 1235.489954] usb-storage: *** thread
awakened.
Nov 17 01:15:06 krabat kernel: [ 1235.489958] usb-storage: Command
READ_10 (10 bytes)
Nov 17 01:15:06 krabat kernel: [ 1235.489961] usb-storage: 28 00 20 c5
41 da 00 00 10 00
Nov 17 01:15:06 krabat kernel: [ 1235.489974] usb-storage: Bulk Command
S 0x43425355 T 0x72e21 L 8192 F 128 Trg 0 LUN 0 CL 10
Nov 17 01:15:06 krabat kernel: [ 1235.489979] usb-storage:
usb_stor_bulk_transfer_buf: xfer 31 bytes
Nov 17 01:15:06 krabat kernel: [ 1235.513844] usb-storage: Status code
0; transferred 31/31
Nov 17 01:15:06 krabat kernel: [ 1235.513847] usb-storage: -- transfer
complete
Nov 17 01:15:06 krabat kernel: [ 1235.513850] usb-storage: Bulk command
transfer result=0
Nov 17 01:15:06 krabat kernel: [ 1235.513853] usb-storage:
usb_stor_bulk_transfer_sglist: xfer 8192 bytes, 1 entries
Nov 17 01:15:06 krabat kernel: [ 1235.515203] usb-storage: Status code
0; transferred 8192/8192
Nov 17 01:15:06 krabat kernel: [ 1235.515205] usb-storage: -- transfer
complete
Nov 17 01:15:06 krabat kernel: [ 1235.515208] usb-storage: Bulk data
transfer result 0x0
Nov 17 01:15:06 krabat kernel: [ 1235.515209] usb-storage: Attempting to
get CSW...
Nov 17 01:15:06 krabat kernel: [ 1235.515212] usb-storage:
usb_stor_bulk_transfer_buf: xfer 13 bytes
Nov 17 01:15:06 krabat kernel: [ 1235.537775] usb-storage: Status code
0; transferred 13/13
Nov 17 01:15:06 krabat kernel: [ 1235.537778] usb-storage: -- transfer
complete
Nov 17 01:15:06 krabat kernel: [ 1235.537780] usb-storage: Bulk status
result = 0
Nov 17 01:15:06 krabat kernel: [ 1235.537783] usb-storage: Bulk Status S
0x53425355 T 0x72e21 R 0 Stat 0x0
Nov 17 01:15:06 krabat kernel: [ 1235.537786] usb-storage: scsi cmd
done, result=0x0
Nov 17 01:15:06 krabat kernel: [ 1235.537790] usb-storage: *** thread
sleeping.
Nov 17 01:15:06 krabat kernel: [ 1235.537808] usb-storage: queuecommand
called
Nov 17 01:15:06 krabat kernel: [ 1235.537819] usb-storage: *** thread
awakened.
Nov 17 01:15:06 krabat kernel: [ 1235.537823] usb-storage: Command
READ_10 (10 bytes)
Nov 17 01:15:06 krabat kernel: [ 1235.537826] usb-storage: 28 00 20 c5
41 ea 00 00 f0 00
Nov 17 01:15:06 krabat kernel: [ 1235.537839] usb-storage: Bulk Command
S 0x43425355 T 0x72e22 L 122880 F 128 Trg 0 LUN 0 CL 10
Nov 17 01:15:06 krabat kernel: [ 1235.537844] usb-storage:
usb_stor_bulk_transfer_buf: xfer 31 bytes
Nov 17 01:15:06 krabat kernel: [ 1235.561711] usb-storage: Status code
0; transferred 31/31
Nov 17 01:15:06 krabat kernel: [ 1235.561714] usb-storage: -- transfer
complete
Nov 17 01:15:06 krabat kernel: [ 1235.561716] usb-storage: Bulk command
transfer result=0
Nov 17 01:15:06 krabat kernel: [ 1235.561719] usb-storage:
usb_stor_bulk_transfer_sglist: xfer 122880 bytes, 19 entries
Nov 17 01:15:06 krabat kernel: [ 1235.569776] ehci_hcd 0000:00:1d.7:
port 1 high speed
Nov 17 01:15:06 krabat kernel: [ 1235.569782] ehci_hcd 0000:00:1d.7:
GetStatus port 1 status 001005 POWER sig=se0 PE CONNECT
Nov 17 01:15:06 krabat kernel: [ 1235.588475] usb-storage: Status code
0; transferred 122880/122880
Nov 17 01:15:06 krabat kernel: [ 1235.588478] usb-storage: -- transfer
complete
Nov 17 01:15:06 krabat kernel: [ 1235.588481] usb-storage: Bulk data
transfer result 0x0
Nov 17 01:15:06 krabat kernel: [ 1235.588483] usb-storage: Attempting to
get CSW...
Nov 17 01:15:06 krabat kernel: [ 1235.588486] usb-storage:
usb_stor_bulk_transfer_buf: xfer 13 bytes
Nov 17 01:15:11 krabat kernel: [ 1240.624209] usb 3-1: usb-storage timed
out on ep0out len=0/0
Nov 17 01:15:11 krabat kernel: [ 1240.624332] usb-storage: Status code
0; transferred 13/13
Nov 17 01:15:11 krabat kernel: [ 1240.624335] usb-storage: -- transfer
complete
Nov 17 01:15:11 krabat kernel: [ 1240.624337] usb-storage: Bulk status
result = 0
Nov 17 01:15:11 krabat kernel: [ 1240.624340] usb-storage: Bulk Status S
0x53425355 T 0x72e22 R 0 Stat 0x0
Nov 17 01:15:11 krabat kernel: [ 1240.624343] usb-storage: scsi cmd
done, result=0x0
Nov 17 01:15:11 krabat kernel: [ 1240.624347] usb-storage: *** thread
sleeping.
Nov 17 01:15:11 krabat kernel: [ 1240.624368] usb-storage: queuecommand
called
Nov 17 01:15:11 krabat kernel: [ 1240.624382] usb-storage: *** thread
awakened.
Nov 17 01:15:11 krabat kernel: [ 1240.624386] usb-storage: Command
READ_10 (10 bytes)
Nov 17 01:15:11 krabat kernel: [ 1240.624388] usb-storage: 28 00 20 c5
42 da 00 00 10 00
Nov 17 01:15:11 krabat kernel: [ 1240.624401] usb-storage: Bulk Command
S 0x43425355 T 0x72e23 L 8192 F 128 Trg 0 LUN 0 CL 10
Nov 17 01:15:11 krabat kernel: [ 1240.624407] usb-storage:
usb_stor_bulk_transfer_buf: xfer 31 bytes
Nov 17 01:15:11 krabat kernel: [ 1240.648270] usb-storage: Status code
0; transferred 31/31
Nov 17 01:15:11 krabat kernel: [ 1240.648274] usb-storage: -- transfer
complete
Nov 17 01:15:11 krabat kernel: [ 1240.648276] usb-storage: Bulk command
transfer result=0
Nov 17 01:15:11 krabat kernel: [ 1240.648279] usb-storage:
usb_stor_bulk_transfer_sglist: xfer 8192 bytes, 2 entries
Nov 17 01:15:11 krabat kernel: [ 1240.672332] usb-storage: Status code
0; transferred 8192/8192
Nov 17 01:15:11 krabat kernel: [ 1240.672335] usb-storage: -- transfer
complete
Nov 17 01:15:11 krabat kernel: [ 1240.672338] usb-storage: Bulk data
transfer result 0x0
Nov 17 01:15:11 krabat kernel: [ 1240.672340] usb-storage: Attempting to
get CSW...
Nov 17 01:15:11 krabat kernel: [ 1240.672343] usb-storage:
usb_stor_bulk_transfer_buf: xfer 13 bytes
Nov 17 01:15:16 krabat kernel: [ 1245.826495] usb 3-1: usb-storage timed
out on ep0out len=0/0
Nov 17 01:15:16 krabat kernel: [ 1245.826550] usb-storage: Status code
0; transferred 13/13
Nov 17 01:15:16 krabat kernel: [ 1245.826552] usb-storage: -- transfer
complete
Nov 17 01:15:16 krabat kernel: [ 1245.826555] usb-storage: Bulk status
result = 0
Nov 17 01:15:16 krabat kernel: [ 1245.826557] usb-storage: Bulk Status S
0x53425355 T 0x72e23 R 0 Stat 0x0
Nov 17 01:15:16 krabat kernel: [ 1245.826561] usb-storage: scsi cmd
done, result=0x0
Nov 17 01:15:16 krabat kernel: [ 1245.826564] usb-storage: *** thread
sleeping.
Nov 17 01:15:16 krabat kernel: [ 1245.826581] usb-storage: queuecommand
called
Nov 17 01:15:16 krabat kernel: [ 1245.826593] usb-storage: *** thread
awakened.
Nov 17 01:15:16 krabat kernel: [ 1245.826597] usb-storage: Command
READ_10 (10 bytes)
Nov 17 01:15:16 krabat kernel: [ 1245.826600] usb-storage: 28 00 20 c5
42 ea 00 00 f0 00
Nov 17 01:15:16 krabat kernel: [ 1245.826613] usb-storage: Bulk Command
S 0x43425355 T 0x72e24 L 122880 F 128 Trg 0 LUN 0 CL 10
Nov 17 01:15:16 krabat kernel: [ 1245.826617] usb-storage:
usb_stor_bulk_transfer_buf: xfer 31 bytes
Nov 17 01:15:16 krabat kernel: [ 1245.850498] usb-storage: Status code
0; transferred 31/31
Nov 17 01:15:16 krabat kernel: [ 1245.850501] usb-storage: -- transfer
complete
Nov 17 01:15:16 krabat kernel: [ 1245.850504] usb-storage: Bulk command
transfer result=0
Nov 17 01:15:16 krabat kernel: [ 1245.850507] usb-storage:
usb_stor_bulk_transfer_sglist: xfer 122880 bytes, 23 entries
Nov 17 01:15:16 krabat kernel: [ 1245.877356] usb-storage: Status code
0; transferred 122880/122880
Nov 17 01:15:16 krabat kernel: [ 1245.877360] usb-storage: -- transfer
complete
Nov 17 01:15:16 krabat kernel: [ 1245.877362] usb-storage: Bulk data
transfer result 0x0
Nov 17 01:15:16 krabat kernel: [ 1245.877364] usb-storage: Attempting to
get CSW...
Nov 17 01:15:16 krabat kernel: [ 1245.877367] usb-storage:
usb_stor_bulk_transfer_buf: xfer 13 bytes
Nov 17 01:15:16 krabat kernel: [ 1246.029964] usb 3-1: device not
accepting address 4, error -110
Nov 17 01:15:16 krabat kernel: [ 1246.086081] ehci_hcd 0000:00:1d.7:
port 1 high speed
Nov 17 01:15:16 krabat kernel: [ 1246.086088] ehci_hcd 0000:00:1d.7:
GetStatus port 1 status 001005 POWER sig=se0 PE CONNECT
--------------------------------------------------

If more infos are needed (or the complete log)...

Regards,

Alexander

2009-11-17 01:11:31

by Alexander Holler

[permalink] [raw]
Subject: Re: Problems with p55-express and sleeping usb-hds

This isn't my time, :(

Am 17.11.2009 01:52, schrieb Alexander Holler:
> Here it is, I haven't cut anything in between and have choosen some
> lines (of the 1gb-log I've got) before and after the first reset-message:
>
> --------------------------------------------------
> Nov 17 01:14:50 krabat kernel: [ 1219.910972] usb-storage: Bulk command
> transfer result=0

that was the second reset message, here is the first:

------------------------
Nov 17 01:14:14 krabat kernel: [ 1184.253782] usb-storage: Bulk data
transfer result 0x0
Nov 17 01:14:14 krabat kernel: [ 1184.253784] usb-storage: Attempting to
get CSW...
Nov 17 01:14:14 krabat kernel: [ 1184.253786] usb-storage:
usb_stor_bulk_transfer_buf: xfer 13 bytes
Nov 17 01:14:14 krabat kernel: [ 1184.253795] usb-storage: Status code
0; transferred 8192/8192
Nov 17 01:14:14 krabat kernel: [ 1184.253797] usb-storage: -- transfer
complete
Nov 17 01:14:14 krabat kernel: [ 1184.253799] usb-storage: Bulk data
transfer result 0x0
Nov 17 01:14:14 krabat kernel: [ 1184.253801] usb-storage: Attempting to
get CSW...
Nov 17 01:14:14 krabat kernel: [ 1184.253804] usb-storage:
usb_stor_bulk_transfer_buf: xfer 13 bytes
Nov 17 01:14:45 krabat kernel: [ 1214.716721] usb-storage: command_abort
called
Nov 17 01:14:45 krabat kernel: [ 1214.716725] usb-storage:
usb_stor_stop_transport called
Nov 17 01:14:45 krabat kernel: [ 1214.716727] usb-storage: -- cancelling URB
Nov 17 01:14:45 krabat kernel: [ 1214.728631] usb-storage: Status code
-104; transferred 0/13
Nov 17 01:14:45 krabat kernel: [ 1214.728634] usb-storage: -- transfer
cancelled
Nov 17 01:14:45 krabat kernel: [ 1214.728637] usb-storage: Bulk status
result = 4
Nov 17 01:14:45 krabat kernel: [ 1214.728639] usb-storage: -- command
was aborted
Nov 17 01:14:45 krabat kernel: [ 1214.728643] usb-storage:
usb_stor_pre_reset
Nov 17 01:14:45 krabat kernel: [ 1214.728738] usb-storage: Status code
0; transferred 13/13
Nov 17 01:14:45 krabat kernel: [ 1214.728741] usb-storage: -- transfer
complete
Nov 17 01:14:45 krabat kernel: [ 1214.728743] usb-storage: Bulk status
result = 0
Nov 17 01:14:45 krabat kernel: [ 1214.728746] usb-storage: Bulk Status S
0x53425355 T 0x72e1b R 0 Stat 0x0
Nov 17 01:14:45 krabat kernel: [ 1214.728750] usb-storage: scsi cmd
done, result=0x0
Nov 17 01:14:45 krabat kernel: [ 1214.728754] usb-storage: *** thread
sleeping.
Nov 17 01:14:45 krabat kernel: [ 1214.728772] usb-storage: queuecommand
called
Nov 17 01:14:45 krabat kernel: [ 1214.728784] usb-storage: *** thread
awakened.
Nov 17 01:14:45 krabat kernel: [ 1214.728788] usb-storage: Command
READ_10 (10 bytes)
Nov 17 01:14:45 krabat kernel: [ 1214.728790] usb-storage: 28 00 20 c5
3e ea 00 00 f0 00
Nov 17 01:14:45 krabat kernel: [ 1214.728804] usb-storage: Bulk Command
S 0x43425355 T 0x72e1c L 122880 F 128 Trg 0 LUN 0 CL 10
Nov 17 01:14:45 krabat kernel: [ 1214.728809] usb-storage:
usb_stor_bulk_transfer_buf: xfer 31 bytes
Nov 17 01:14:45 krabat kernel: [ 1214.752624] usb-storage: Status code
0; transferred 31/31
Nov 17 01:14:45 krabat kernel: [ 1214.752627] usb-storage: -- transfer
complete
Nov 17 01:14:45 krabat kernel: [ 1214.752629] usb-storage: Bulk command
transfer result=0
Nov 17 01:14:45 krabat kernel: [ 1214.752633] usb-storage:
usb_stor_bulk_transfer_sglist: xfer 122880 bytes, 8 entries
Nov 17 01:14:45 krabat kernel: [ 1214.779473] usb-storage: Status code
0; transferred 122880/122880
Nov 17 01:14:45 krabat kernel: [ 1214.779476] usb-storage: -- transfer
complete
Nov 17 01:14:45 krabat kernel: [ 1214.779478] usb-storage: Bulk data
transfer result 0x0
Nov 17 01:14:45 krabat kernel: [ 1214.779480] usb-storage: Attempting to
get CSW...
Nov 17 01:14:45 krabat kernel: [ 1214.779483] usb-storage:
usb_stor_bulk_transfer_buf: xfer 13 bytes
Nov 17 01:14:45 krabat kernel: [ 1214.784753] ehci_hcd 0000:00:1d.7:
port 1 high speed
Nov 17 01:14:45 krabat kernel: [ 1214.784760] ehci_hcd 0000:00:1d.7:
GetStatus port 1 status 001005 POWER sig=se0 PE CONNECT
Nov 17 01:14:45 krabat kernel: [ 1214.840337] usb 3-1: reset high speed
USB device using ehci_hcd and address 4
Nov 17 01:14:50 krabat kernel: [ 1219.839123] usb 3-1: usb-storage timed
out on ep0in len=0/64
Nov 17 01:14:50 krabat kernel: [ 1219.839213] usb-storage: Status code
0; transferred 13/13
Nov 17 01:14:50 krabat kernel: [ 1219.839216] usb-storage: -- transfer
complete
Nov 17 01:14:50 krabat kernel: [ 1219.839218] usb-storage: Bulk status
result = 0
Nov 17 01:14:50 krabat kernel: [ 1219.839221] usb-storage: Bulk Status S
0x53425355 T 0x72e1c R 0 Stat 0x0
Nov 17 01:14:50 krabat kernel: [ 1219.839225] usb-storage: scsi cmd
done, result=0x0
Nov 17 01:14:50 krabat kernel: [ 1219.839229] usb-storage: *** thread
sleeping.
Nov 17 01:14:50 krabat kernel: [ 1219.839250] usb-storage: queuecommand
called
Nov 17 01:14:50 krabat kernel: [ 1219.839263] usb-storage: *** thread
awakened.
Nov 17 01:14:50 krabat kernel: [ 1219.839267] usb-storage: Command
READ_10 (10 bytes)
Nov 17 01:14:50 krabat kernel: [ 1219.839270] usb-storage: 28 00 20 c5
3f da 00 00 10 00
Nov 17 01:14:50 krabat kernel: [ 1219.839283] usb-storage: Bulk Command
S 0x43425355 T 0x72e1d L 8192 F 128 Trg 0 LUN 0 CL 10
Nov 17 01:14:50 krabat kernel: [ 1219.839288] usb-storage:
usb_stor_bulk_transfer_buf: xfer 31 bytes
Nov 17 01:14:50 krabat kernel: [ 1219.863238] usb-storage: Status code
0; transferred 31/31
Nov 17 01:14:50 krabat kernel: [ 1219.863241] usb-storage: -- transfer
complete
Nov 17 01:14:50 krabat kernel: [ 1219.863243] usb-storage: Bulk command
transfer result=0
Nov 17 01:14:50 krabat kernel: [ 1219.863246] usb-storage:
usb_stor_bulk_transfer_sglist: xfer 8192 bytes, 2 entries
Nov 17 01:14:50 krabat kernel: [ 1219.864602] usb-storage: Status code
0; transferred 8192/8192
Nov 17 01:14:50 krabat kernel: [ 1219.864605] usb-storage: -- transfer
complete
Nov 17 01:14:50 krabat kernel: [ 1219.864607] usb-storage: Bulk data
transfer result 0x0
Nov 17 01:14:50 krabat kernel: [ 1219.864609] usb-storage: Attempting to
get CSW...
Nov 17 01:14:50 krabat kernel: [ 1219.864612] usb-storage:
usb_stor_bulk_transfer_buf: xfer 13 bytes
Nov 17 01:14:50 krabat kernel: [ 1219.887021] usb-storage: Status code
0; transferred 13/13
Nov 17 01:14:50 krabat kernel: [ 1219.887024] usb-storage: -- transfer
complete
Nov 17 01:14:50 krabat kernel: [ 1219.887027] usb-storage: Bulk status
result = 0
Nov 17 01:14:50 krabat kernel: [ 1219.887030] usb-storage: Bulk Status S
0x53425355 T 0x72e1d R 0 Stat 0x0
Nov 17 01:14:50 krabat kernel: [ 1219.887033] usb-storage: scsi cmd
done, result=0x0
Nov 17 01:14:50 krabat kernel: [ 1219.887037] usb-storage: *** thread
sleeping.
Nov 17 01:14:50 krabat kernel: [ 1219.887053] usb-storage: queuecommand
called
Nov 17 01:14:50 krabat kernel: [ 1219.887064] usb-storage: *** thread
awakened.
Nov 17 01:14:50 krabat kernel: [ 1219.887068] usb-storage: Command
READ_10 (10 bytes)
Nov 17 01:14:50 krabat kernel: [ 1219.887071] usb-storage: 28 00 20 c5
3f ea 00 00 f0 00
Nov 17 01:14:50 krabat kernel: [ 1219.887083] usb-storage: Bulk Command
S 0x43425355 T 0x72e1e L 122880 F 128 Trg 0 LUN 0 CL 10
Nov 17 01:14:50 krabat kernel: [ 1219.887089] usb-storage:
usb_stor_bulk_transfer_buf: xfer 31 bytes
Nov 17 01:14:50 krabat kernel: [ 1219.910966] usb-storage: Status code
0; transferred 31/31
Nov 17 01:14:50 krabat kernel: [ 1219.910969] usb-storage: -- transfer
complete
Nov 17 01:14:50 krabat kernel: [ 1219.910972] usb-storage: Bulk command
transfer result=0
> --------------------------------------------------
>
> If more infos are needed (or the complete log)...
>
> Regards,
>
> Alexander

2009-11-17 23:05:57

by Alexander Holler

[permalink] [raw]
Subject: Re: Problems with p55-express and sleeping usb-hds

Hello,

I've done some more tests and have some more findings.

After the problem occured (which looks for me like a timeout during a
wait for a CSW), ehci_hcd doesn't work anymore. Low- and full-speed
devices are still working and are recognized correctly, but no
high-speed device. After unloading ehci_hcd and reloading it, high-speed
devices are recognized correctly again.
As unloading is no option for kernels which have ehci_hcd compiled in
(like the F11-kernel), is there another option to reset the driver?

Regards,

Alexander

2009-11-18 16:22:23

by Alan Stern

[permalink] [raw]
Subject: Re: Problems with p55-express and sleeping usb-hds

On Wed, 18 Nov 2009, Alexander Holler wrote:

> Hello,
>
> I've done some more tests and have some more findings.
>
> After the problem occured (which looks for me like a timeout during a
> wait for a CSW), ehci_hcd doesn't work anymore. Low- and full-speed
> devices are still working and are recognized correctly, but no
> high-speed device. After unloading ehci_hcd and reloading it, high-speed
> devices are recognized correctly again.
> As unloading is no option for kernels which have ehci_hcd compiled in
> (like the F11-kernel), is there another option to reset the driver?

You can unbind ehci-hcd from the controller by writing the controller's
name to the "unbind" attribute in the appropriate sysfs directory. For
example, on my system:

# ls /sys/bus/pci/drivers/ehci_hcd
0000:00:1d.7 0000:01:00.2 0000:01:01.2 bind module new_id uevent
unbind
# echo -n 0000:00:1d.7 >/sys/bus/pci/drivers/ehci_hcd/unbind

Then to rebind the driver, write the device name to the "bind"
attribute:

# echo -n 0000:00:1d.7 >/sys/bus/pci/drivers/ehci_hcd/bind

Alan Stern

2009-12-10 22:28:41

by Alexander Holler

[permalink] [raw]
Subject: Re: Problems with p55-express and sleeping usb-hds

Am 18.11.2009 17:22, schrieb Alan Stern:

> You can unbind ehci-hcd from the controller by writing the controller's
> name to the "unbind" attribute in the appropriate sysfs directory. For
> example, on my system:
>
> # ls /sys/bus/pci/drivers/ehci_hcd
> 0000:00:1d.7 0000:01:00.2 0000:01:01.2 bind module new_id uevent
> unbind
> # echo -n 0000:00:1d.7>/sys/bus/pci/drivers/ehci_hcd/unbind
>
> Then to rebind the driver, write the device name to the "bind"
> attribute:
>
> # echo -n 0000:00:1d.7>/sys/bus/pci/drivers/ehci_hcd/bind

Thanks, that works nicely and takes away the need to reboot when using a
stock F11 kernel and the problem occurs.

I've recently discovered that I can provoke the error too, when using dd
on an usb-dvd writing the output to an usb-hdd. So the topic of this
thread is now certainly wrong.

And because I'm still having the problem using Kernel 2.6.31.7 and
2.6.32, I've written bug #14785. It's easier to attach long logs there.

Kind regards,

Alexander Holler