Re: PROBLEM: hotplugging an USB memorystick fails

* Alan Stern <[email protected]> [071018 20:22]:
> On Wed, 17 Oct 2007, I Mouwen wrote:
>
> > Here's the kernel log with debugging enabled. This is when I insert
> > the memory stick after booting.
>
> ...
> > Oct 17 21:13:40 casper kernel: scsi scan: INQUIRY result too short (5), using 36
>
> That's not a terribly bad error.  It merely means the device included a
> bad length byte in its INQUIRY data.  However it is surprising that
> this message did not appear in the insert-before-boot log.
>

My apologies, it seems I was too rigorous with my grepping. That message
does indeed appear in the insert-before-boot log.

As suggested by Oliver I just got a usbmon trace while inserting the stick.

> > Oct 17 21:13:40 casper kernel: usb-storage: *** thread sleeping.
> > Oct 17 21:13:40 casper kernel: sd 4:0:0:0: [sda] Attached SCSI disk
> > Oct 17 21:13:40 casper kernel: usb-storage: queuecommand called
> > Oct 17 21:13:40 casper kernel: usb-storage: *** thread awakened.
> > Oct 17 21:13:40 casper kernel: usb-storage: Command INQUIRY (6 bytes)
> > Oct 17 21:13:40 casper kernel: usb-storage:  12 00 00 00 fe 00
>
> This and the following commands look very bizarre.  They resemble
> something that might be produced by a several-year-old version of HAL
> or some other drive-monitoring program.

Hm, I run a pretty recent debian unstable, so it's most certainly not a
several-year-old hal. Do you have a suggestion how I might debug this?


Regards,

Iwan Mouwen

--- usbmon ---
ffff81003e0d4b00 429069961 S Ii:2:001:1 -115:2048 4 <
ffff81003d96d300 429070037 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
ffff81003d96d300 429070044 C Ci:2:001:0 0 4 = 00010000
ffff81003d96d300 429070068 S Ci:2:001:0 s a3 00 0000 0002 0004 4 <
ffff81003d96d300 429070072 C Ci:2:001:0 0 4 = 00010000
ffff81003d96d300 429070090 S Ci:2:001:0 s a3 00 0000 0003 0004 4 <
ffff81003d96d300 429070094 C Ci:2:001:0 0 4 = 00010000
ffff81003d96d300 429070112 S Ci:2:001:0 s a3 00 0000 0004 0004 4 <
ffff81003d96d300 429070115 C Ci:2:001:0 0 4 = 00010000
ffff81003d96d300 429070134 S Ci:2:001:0 s a3 00 0000 0005 0004 4 <
ffff81003d96d300 429070138 C Ci:2:001:0 0 4 = 01050100
ffff81003d96d300 429070156 S Co:2:001:0 s 23 01 0010 0005 0000 0
ffff81003d96d300 429070160 C Co:2:001:0 0 0
ffff81003d96d300 429070177 S Ci:2:001:0 s a3 00 0000 0005 0004 4 <
ffff81003d96d300 429070181 C Ci:2:001:0 0 4 = 01050000
ffff81003d96d300 429102000 S Ci:2:001:0 s a3 00 0000 0005 0004 4 <
ffff81003d96d300 429102004 C Ci:2:001:0 0 4 = 01050000
ffff81003d96d300 429133959 S Ci:2:001:0 s a3 00 0000 0005 0004 4 <
ffff81003d96d300 429133964 C Ci:2:001:0 0 4 = 01050000
ffff81003d96d300 429165955 S Ci:2:001:0 s a3 00 0000 0005 0004 4 <
ffff81003d96d300 429165960 C Ci:2:001:0 0 4 = 01050000
ffff81003d96d300 429197954 S Ci:2:001:0 s a3 00 0000 0005 0004 4 <
ffff81003d96d300 429197957 C Ci:2:001:0 0 4 = 01050000
ffff81003d96d300 429197983 S Co:2:001:0 s 23 03 0004 0005 0000 0
ffff81003d96d300 429197988 C Co:2:001:0 0 0
ffff81003d96d300 429253984 S Ci:2:001:0 s a3 00 0000 0005 0004 4 <
ffff81003d96d300 429254225 C Ci:2:001:0 0 4 = 03051000
ffff81003d96d300 429309952 S Co:2:001:0 s 23 01 0014 0005 0000 0
ffff81003d96d300 429309956 C Co:2:001:0 0 0
ffff81003d96d900 429310206 S Ci:2:000:0 s 80 06 0100 0000 0040 64 <
ffff81003d96d900 429312478 C Ci:2:000:0 0 18 = 12010002 09000140
e0131525 00010103 0001
ffff81003d96d900 429312497 S Co:2:001:0 s 23 03 0004 0005 0000 0
ffff81003d96d900 429312502 C Co:2:001:0 0 0
ffff81003d96d900 429369949 S Ci:2:001:0 s a3 00 0000 0005 0004 4 <
ffff81003d96d900 429370178 C Ci:2:001:0 0 4 = 03051000
ffff81003d96d900 429425946 S Co:2:001:0 s 23 01 0014 0005 0000 0
ffff81003d96d900 429425951 C Co:2:001:0 0 0
ffff81003d96d900 429425974 S Co:2:000:0 s 00 05 000d 0000 0000 0
ffff81003d96d900 429426099 C Co:2:000:0 0 0
ffff81003d96d900 429445946 S Ci:2:013:0 s 80 06 0100 0000 0012 18 <
ffff81003d96d900 429448098 C Ci:2:013:0 0 18 = 12010002 09000140
e0131525 00010103 0001
ffff81003d96d900 429448119 S Ci:2:013:0 s 80 06 0200 0000 0009 9 <
ffff81003d96d900 429450222 C Ci:2:013:0 0 9 = 09022200 010100c0 32
ffff81003d96d900 429450238 S Ci:2:013:0 s 80 06 0200 0000 0022 34 <
ffff81003d96d900 429452472 C Ci:2:013:0 0 34 = 09022200 010100c0
32090400 00010900 00000705 81030100 0c092901 0d003264
ffff81003d96d900 429452501 S Ci:2:013:0 s 80 06 0300 0000 00ff 255 <
ffff81003d96d900 429454598 C Ci:2:013:0 0 4 = 04030904
ffff81003d96d900 429454615 S Ci:2:013:0 s 80 06 0303 0409 00ff 255 <
ffff81003d96d900 429456847 C Ci:2:013:0 0 34 = 22035500 53004200
20004500 6d006200 65006400 64006500 64002000 48007500
ffff81003d96d900 429456868 S Ci:2:013:0 s 80 06 0301 0409 00ff 255 <
ffff81003d96d900 429458973 C Ci:2:013:0 0 18 = 12035400 53004500
20004900 6e006300 2e00
ffff81003d96d900 429459339 S Co:2:013:0 s 00 09 0001 0000 0000 0
ffff81003d96d900 429459474 C Co:2:013:0 0 0
ffff81003d96d900 429459695 S Ci:2:013:0 s a0 06 2900 0000 000f 15 <
ffff81003d96d900 429459849 C Ci:2:013:0 0 9 = 0929010d 00326402 ff
ffff81003d96d900 429460026 S Ci:2:013:0 s 80 00 0000 0000 0002 2 <
ffff81003d96d900 429460223 C Ci:2:013:0 0 2 = 0100
ffff81003d96d900 429460379 S Ci:2:013:0 s a0 00 0000 0000 0004 4 <
ffff81003d96d900 429460598 C Ci:2:013:0 0 4 = 01000000
ffff81003d96d840 429460621 S Co:2:013:0 s 23 03 0008 0001 0000 0
ffff81003d96d840 429460848 C Co:2:013:0 0 0
ffff81003d96d900 429566310 S Ii:2:013:1 -115:2048 1 <
ffff81003d96d840 429567488 S Ci:2:001:0 s a3 00 0000 0006 0004 4 <
ffff81003d96d840 429567495 C Ci:2:001:0 0 4 = 00010000
ffff81003d96d840 429567524 S Ci:2:001:0 s a3 00 0000 0007 0004 4 <
ffff81003d96d840 429567528 C Ci:2:001:0 0 4 = 00010000
ffff81003d96d840 429567560 S Ci:2:001:0 s a3 00 0000 0008 0004 4 <
ffff81003d96d840 429567564 C Ci:2:001:0 0 4 = 00010000
ffff81003d96d840 429567583 S Ci:2:001:0 s a3 00 0000 0009 0004 4 <
ffff81003d96d840 429567586 C Ci:2:001:0 0 4 = 00010000
ffff81003d96d840 429567604 S Ci:2:001:0 s a3 00 0000 000a 0004 4 <
ffff81003d96d840 429567608 C Ci:2:001:0 0 4 = 00010000
ffff81003d96d840 429567629 S Ci:2:013:0 s a3 00 0000 0001 0004 4 <
ffff81003d96d840 429567847 C Ci:2:013:0 0 4 = 01050100
ffff81003d96d840 429567871 S Co:2:013:0 s 23 01 0010 0001 0000 0
ffff81003d96d840 429568094 C Co:2:013:0 0 0
ffff81003d96d840 429568116 S Ci:2:013:0 s a3 00 0000 0001 0004 4 <
ffff81003d96d840 429568219 C Ci:2:013:0 0 4 = 01050000
ffff81003d96d840 429599272 S Ci:2:013:0 s a3 00 0000 0001 0004 4 <
ffff81003d96d840 429599472 C Ci:2:013:0 0 4 = 01050000
ffff81003d96d840 429629940 S Ci:2:013:0 s a3 00 0000 0001 0004 4 <
ffff81003d96d840 429630093 C Ci:2:013:0 0 4 = 01050000
ffff81003d96d840 429661938 S Ci:2:013:0 s a3 00 0000 0001 0004 4 <
ffff81003d96d840 429662092 C Ci:2:013:0 0 4 = 01050000
ffff81003d96d840 429693935 S Ci:2:013:0 s a3 00 0000 0001 0004 4 <
ffff81003d96d840 429694091 C Ci:2:013:0 0 4 = 01050000
ffff81003d96d840 429694114 S Co:2:013:0 s 23 03 0004 0001 0000 0
ffff81003d96d840 429694340 C Co:2:013:0 0 0
ffff81003d96d840 429709936 S Ci:2:013:0 s a3 00 0000 0001 0004 4 <
ffff81003d96d840 429710091 C Ci:2:013:0 0 4 = 03051000
ffff81003d96d840 429765933 S Co:2:013:0 s 23 01 0014 0001 0000 0
ffff81003d96d840 429766088 C Co:2:013:0 0 0
ffff81003d96d840 429766319 S Ci:2:000:0 s 80 06 0100 0000 0040 64 <
ffff81003d96d840 429768714 C Ci:2:000:0 0 18 = 12010002 00000040
e0131725 00010104 0001
ffff81003d96d840 429768735 S Co:2:013:0 s 23 03 0004 0001 0000 0
ffff81003d96d840 429768963 C Co:2:013:0 0 0
ffff81003d96d840 429785985 S Ci:2:013:0 s a3 00 0000 0001 0004 4 <
ffff81003d96d840 429786088 C Ci:2:013:0 0 4 = 03051000
ffff81003d96d840 429841930 S Co:2:013:0 s 23 01 0014 0001 0000 0
ffff81003d96d840 429842087 C Co:2:013:0 0 0
ffff81003d96d840 429842104 S Co:2:000:0 s 00 05 000e 0000 0000 0
ffff81003d96d840 429842586 C Co:2:000:0 0 0
ffff81003d96d840 429861931 S Ci:2:014:0 s 80 06 0100 0000 0012 18 <
ffff81003d96d840 429864211 C Ci:2:014:0 0 18 = 12010002 00000040
e0131725 00010104 0001
ffff81003d96d840 429864234 S Ci:2:014:0 s 80 06 0200 0000 0009 9 <
ffff81003d96d840 429866459 C Ci:2:014:0 0 9 = 09022000 010100c0 00
ffff81003d96d840 429866476 S Ci:2:014:0 s 80 06 0200 0000 0020 32 <
ffff81003d96d840 429868710 C Ci:2:014:0 0 32 = 09022000 010100c0
00090400 00020806 50000705 01020002 00070582 02000200
ffff81003d96d840 429868736 S Ci:2:014:0 s 80 06 0300 0000 00ff 255 <
ffff81003d96d840 429870835 C Ci:2:014:0 0 4 = 04030904
ffff81003d96d840 429870850 S Ci:2:014:0 s 80 06 0304 0409 00ff 255 <
ffff81003d96d840 429873086 C Ci:2:014:0 0 48 = 30035500 53004200
20004d00 61007300 73002000 53007400 6f007200 61006700
ffff81003d96d840 429873107 S Ci:2:014:0 s 80 06 0301 0409 00ff 255 <
ffff81003d96d840 429875335 C Ci:2:014:0 0 18 = 12035400 53004500
20004900 6e006300 2e00
ffff81003d96d840 429876401 S Co:2:014:0 s 00 09 0001 0000 0000 0
ffff81003d96d840 429876587 C Co:2:014:0 0 0
ffff81001c25a5c0 434877769 S Ci:2:014:0 s a1 fe 0000 0000 0001 1 <
ffff81001c25a5c0 434877940 C Ci:2:014:0 0 1 = 00
ffff81001c25a5c0 434878378 S Bo:2:014:1 -115 31 = 55534243 01000000
24000000 80000612 00000024 00000000 00000000 000000
ffff81001c25a5c0 434879437 C Bo:2:014:1 0 31 >
ffff81001c25a740 434879459 S Bi:2:014:2 -115 36 <
ffff81001c25a740 434879936 C Bi:2:014:2 0 36 = 00000000 00000000
55534220 20202020 322e3020 466c6173 68204472 69766500
ffff81001c25a5c0 434879959 S Bi:2:014:2 -115 13 <
ffff81001c25a5c0 434880061 C Bi:2:014:2 0 13 = 55534253 01000000 00000000 00
ffff81001c25a5c0 434881605 S Bo:2:014:1 -115 31 = 55534243 02000000
00000000 00000600 00000000 00000000 00000000 000000
ffff81001c25a5c0 434881813 C Bo:2:014:1 0 31 >
ffff81001c25a5c0 434881835 S Bi:2:014:2 -115 13 <
ffff81001c25a5c0 434882437 C Bi:2:014:2 0 13 = 55534253 02000000 00000000 01
ffff81001c25a5c0 434882480 S Bo:2:014:1 -115 31 = 55534243 03000000
12000000 80000603 00000012 00000000 00000000 000000
ffff81001c25a5c0 434882685 C Bo:2:014:1 0 31 >
ffff81001c25a5c0 434882700 S Bi:2:014:2 -115 18 <
ffff81001c25a5c0 434883437 C Bi:2:014:2 0 18 = 70000600 0000000a
00000000 3a000000 0000
ffff81001c25a5c0 434883455 S Bi:2:014:2 -115 13 <
ffff81001c25a5c0 434883561 C Bi:2:014:2 0 13 = 55534253 03000000 00000000 00
ffff81001c25a5c0 434996103 S Bo:2:014:1 -115 31 = 55534243 04000000
fe000000 80000612 000000fe 00000000 00000000 000000
ffff81001c25a5c0 434996186 C Bo:2:014:1 0 31 >
ffff81001c25a200 434996215 S Bi:2:014:2 -115 254 <
ffff81001c25a200 434996683 C Bi:2:014:2 -121 36 = 00000000 00000000
55534220 20202020 322e3020 466c6173 68204472 69766500
ffff81001c25a5c0 434996711 S Bi:2:014:2 -115 13 <
ffff81001c25a5c0 434996933 C Bi:2:014:2 0 13 = 55534253 04000000 da000000 00
ffff81001c25a5c0 434997075 S Bo:2:014:1 -115 31 = 55534243 05000000
fe000000 80000612 010000fe 00000000 00000000 000000
ffff81001c25a5c0 434997433 C Bo:2:014:1 0 31 >
ffff81001c25a200 434997455 S Bi:2:014:2 -115 254 <
ffff81001c25a200 434997933 C Bi:2:014:2 -121 36 = 00000000 00000000
55534220 20202020 322e3020 466c6173 68204472 69766500
ffff81001c25a5c0 434997961 S Bi:2:014:2 -115 13 <
ffff81001c25a5c0 434998433 C Bi:2:014:2 0 13 = 55534253 05000000 da000000 00

-------------------------------------------------------------------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems?  Stop.
Now Search log events and configuration files using AJAX and a browser.
Download your FREE copy of Splunk now >> http://get.splunk.com/
_______________________________________________
[email protected]
To unsubscribe, use the last form field at:
https://lists.sourceforge.net/lists/listinfo/linux-usb-devel