Bug 8885

Summary: Unable to access memory card reader anymore
Product: Drivers Reporter: Christian Casteyde (casteyde.christian)
Component: USBAssignee: Alan Stern (stern)
Status: CLOSED CODE_FIX    
Severity: normal CC: bunk, protasnb, stern
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: 2.6.23-rc3 Subsystem:
Regression: Yes Bisected commit-id:
Attachments: dmesg for 2.6.22.1-cfs19, which works nice
dmesg for 2.6.23-rc3, which doesn't detect the card
dmesg for 2.6.22 before plugging card
dmesg for 2.6.22 after plugging the card
lspci -v for 2.6.22
lsusb -v for 2.6.22
dmesg for 2.6.23-rc3 before udev
dmesg for 2.6.23-rc3 before plugging the device
lspci -v for 2.6.23 after plugging the device
lsusb -v for 2.6.23-rc3
dmesg for 2.6.23-rc3 with card plugged at boot time
Debug dmesg before udev start
Debug dmesg before after udev, before plugging the card
Debug dmesg before after plugging the card
Debug dmesg after blockdev / rereadpt
dmesg for 2.6.22 with annotations but without HAL
dmesg for 2.6.23 with annotations but without HAL
Reduce number of READ CAPACITY retries
dmesg for 2.6.23-rc3 with sd.c patched (READ_CAPACITY)
Prevent the SGS Thomson card reader from autosuspending
dmesg for 2.6.23+patch no autosuspend = OK

Description Christian Casteyde 2007-08-13 09:14:28 UTC
Most recent kernel where this bug did not occur: 2.6.22.1, maybe 2.6.23-rc2
Distribution: Slackware 12.0
Hardware Environment: Athlon64 3000, laptop Aspire 1511LMi, nForce3 150
Software Environment: Kernel 2.6.23-rc3, blockdev, udev, KDE 3.5.7
Problem Description:
With kernel 2.6.22.1, when I plug a memory card in the integrated card reader of my laptop, the card is detected and KDE(via udev) asks me for mounting the device.
With kernel 2.6.23-rc3, this does not happens anymore:
- first, at boot, there are some new lines in dmesg saying /dev/sda is seen but size cannot be get (normal: there is no memory card in the reader);
- second, plugging the card does nothing;
- third, issuing "blockdev --rereadpt /dev/sda" does not work;
- finally, fdisk /dev/sda fails (unable to open /dev/sda).
So the device seems to be completly unusable now (this is a Thomson card reader if I remember well).

dmesg output for 2.6.22.1-cfs19 and 2.6.23-rc3 appended to show the differences.

Steps to reproduce:
Maybe the problem is specific to my hardware. I presume: boot with an empty card reader connected, the plug the card and see it is inaccessible?
Comment 1 Christian Casteyde 2007-08-13 09:15:24 UTC
Created attachment 12364 [details]
dmesg for 2.6.22.1-cfs19, which works nice
Comment 2 Christian Casteyde 2007-08-13 09:17:05 UTC
Created attachment 12365 [details]
dmesg for 2.6.23-rc3, which doesn't detect the card

Please ignore the cat /proc/acpi/battery/BAT1/state line, this is intended for another bug report (no more battery info with 2.6.23-rc3).
Comment 3 Anonymous Emailer 2007-08-13 20:21:54 UTC
Reply-To: akpm@linux-foundation.org

On Mon, 13 Aug 2007 09:07:36 -0700 (PDT) bugme-daemon@bugzilla.kernel.org wrote:

> http://bugzilla.kernel.org/show_bug.cgi?id=8885
> 
>            Summary: Unable to access memory card reader anymore
>            Product: IO/Storage
>            Version: 2.5
>      KernelVersion: 2.6.23-rc3
>           Platform: All
>         OS/Version: Linux
>               Tree: Mainline
>             Status: NEW
>           Severity: normal
>           Priority: P1
>          Component: SCSI
>         AssignedTo: io_scsi@kernel-bugs.osdl.org
>         ReportedBy: casteyde.christian@free.fr
> 
> 
> Most recent kernel where this bug did not occur: 2.6.22.1, maybe 2.6.23-rc2
> Distribution: Slackware 12.0
> Hardware Environment: Athlon64 3000, laptop Aspire 1511LMi, nForce3 150
> Software Environment: Kernel 2.6.23-rc3, blockdev, udev, KDE 3.5.7
> Problem Description:
> With kernel 2.6.22.1, when I plug a memory card in the integrated card reader
> of my laptop, the card is detected and KDE(via udev) asks me for mounting the
> device.
> With kernel 2.6.23-rc3, this does not happens anymore:
> - first, at boot, there are some new lines in dmesg saying /dev/sda is seen
> but
> size cannot be get (normal: there is no memory card in the reader);
> - second, plugging the card does nothing;
> - third, issuing "blockdev --rereadpt /dev/sda" does not work;
> - finally, fdisk /dev/sda fails (unable to open /dev/sda).
> So the device seems to be completly unusable now (this is a Thomson card
> reader
> if I remember well).
> 
> dmesg output for 2.6.22.1-cfs19 and 2.6.23-rc3 appended to show the
> differences.
> 
> Steps to reproduce:
> Maybe the problem is specific to my hardware. I presume: boot with an empty
> card reader connected, the plug the card and see it is inaccessible?
> 

I'm struggling a bit to work out if this is a scsi bug, a USB bug, an MMC bug
or whatever.  But it's a bug.

Michal, can you please track this as a post-2.6.22 regression?

Others: can you please take a look at the dmesg output, see if we can work
out which subsystem is (newly) failing?

Thanks.
Comment 4 Anonymous Emailer 2007-08-13 21:26:57 UTC
Reply-To: James.Bottomley@SteelEye.com

> I'm struggling a bit to work out if this is a scsi bug, a USB bug, an MMC bug
> or whatever.  But it's a bug.
> 
> Michal, can you please track this as a post-2.6.22 regression?
> 
> Others: can you please take a look at the dmesg output, see if we can work
> out which subsystem is (newly) failing?

There's not enough info in the dmesg.  We really need the dmesg when
it's failing, not when it's booting up, so after the 

blockdev --rereadpt /dev/sda

and the

fdisk /dev/sda

If no messages at all, that's also significant (and I'd guess problems
with media change propagation).

James
Comment 5 Anonymous Emailer 2007-08-13 21:52:15 UTC
Reply-To: drzeus@drzeus.cx

On Mon, 13 Aug 2007 20:13:54 -0700
Andrew Morton <akpm@linux-foundation.org> wrote:

> 
> I'm struggling a bit to work out if this is a scsi bug, a USB bug, an
> MMC bug or whatever.  But it's a bug.
> 

I can't see anything MMC related in his dmesg, only what seems to be a
USB based reader:

scsi 0:0:0:0: Direct-Access     Generic  Flash R/W        2002 PQ: 0
ANSI: 2

Rgds
Pierre
Comment 6 Anonymous Emailer 2007-08-13 22:01:40 UTC
Reply-To: akpm@linux-foundation.org


(resend, fixed mailing list address)

On Mon, 13 Aug 2007 09:07:36 -0700 (PDT) bugme-daemon@bugzilla.kernel.org wrote:

> http://bugzilla.kernel.org/show_bug.cgi?id=8885
> 
>            Summary: Unable to access memory card reader anymore
>            Product: IO/Storage
>            Version: 2.5
>      KernelVersion: 2.6.23-rc3
>           Platform: All
>         OS/Version: Linux
>               Tree: Mainline
>             Status: NEW
>           Severity: normal
>           Priority: P1
>          Component: SCSI
>         AssignedTo: io_scsi@kernel-bugs.osdl.org
>         ReportedBy: casteyde.christian@free.fr
> 
> 
> Most recent kernel where this bug did not occur: 2.6.22.1, maybe 2.6.23-rc2
> Distribution: Slackware 12.0
> Hardware Environment: Athlon64 3000, laptop Aspire 1511LMi, nForce3 150
> Software Environment: Kernel 2.6.23-rc3, blockdev, udev, KDE 3.5.7
> Problem Description:
> With kernel 2.6.22.1, when I plug a memory card in the integrated card reader
> of my laptop, the card is detected and KDE(via udev) asks me for mounting the
> device.
> With kernel 2.6.23-rc3, this does not happens anymore:
> - first, at boot, there are some new lines in dmesg saying /dev/sda is seen
> but
> size cannot be get (normal: there is no memory card in the reader);
> - second, plugging the card does nothing;
> - third, issuing "blockdev --rereadpt /dev/sda" does not work;
> - finally, fdisk /dev/sda fails (unable to open /dev/sda).
> So the device seems to be completly unusable now (this is a Thomson card
> reader
> if I remember well).
> 
> dmesg output for 2.6.22.1-cfs19 and 2.6.23-rc3 appended to show the
> differences.
> 
> Steps to reproduce:
> Maybe the problem is specific to my hardware. I presume: boot with an empty
> card reader connected, the plug the card and see it is inaccessible?
> 

I'm struggling a bit to work out if this is a scsi bug, a USB bug, an MMC bug
or whatever.  But it's a bug.

Michal, can you please track this as a post-2.6.22 regression?

Others: can you please take a look at the dmesg output, see if we can work
out which subsystem is (newly) failing?

Thanks.
Comment 7 Christian Casteyde 2007-08-14 02:25:57 UTC
Here are a little more info.
I append more precise dmesg, as well as lspci and lsusb -v for both kernel.
Comment 8 Christian Casteyde 2007-08-14 02:27:43 UTC
Created attachment 12372 [details]
dmesg for 2.6.22 before plugging card

udev is already started, but the memory card is not plugged.
At boot however, /dev/sda appeared in slack's logs, so the memory card reader has been seen I think. However, there was no attempt to access the device yet.
Comment 9 Christian Casteyde 2007-08-14 02:29:12 UTC
Created attachment 12373 [details]
dmesg for 2.6.22 after plugging the card

When I plug the card in the reader, I clearly can see the probe for the block device, and as it is effectively here, it is seen, corrrectly detected.
Comment 10 Christian Casteyde 2007-08-14 02:30:07 UTC
Created attachment 12374 [details]
lspci -v for 2.6.22

For device identification
Comment 11 Christian Casteyde 2007-08-14 02:30:41 UTC
Created attachment 12375 [details]
lsusb -v for 2.6.22
Comment 12 Christian Casteyde 2007-08-14 02:31:53 UTC
Created attachment 12376 [details]
dmesg for 2.6.23-rc3 before udev

I modified my boot script to get dmesg output just before starting udev.
The device is clearly not present yet.
Comment 13 Christian Casteyde 2007-08-14 02:34:33 UTC
Created attachment 12377 [details]
dmesg for 2.6.23-rc3 before plugging the device

This is dmesg just after boot and udev start up.
As we can see, the device has been probbed, but since there is no card in it, it cannot access it (and it may be blacklisted after?).
Inserting and removing the device does strictly nothing, as well as trying to access it with fdisk, mount or whatsoever. The device is simply unusable.
I suspect a device access race condition, or something like that, since in 2.6.22 the device is not accessed until it is plugged. Maybe a udev bug?
Comment 14 Christian Casteyde 2007-08-14 02:35:47 UTC
Created attachment 12378 [details]
lspci -v for 2.6.23 after plugging the device

2.6.23-rc3 log, in case the device is not well detected (don't think so, seems to be detected too early instead).
Comment 15 Christian Casteyde 2007-08-14 02:37:41 UTC
Created attachment 12379 [details]
lsusb -v for 2.6.23-rc3
Comment 16 Christian Casteyde 2007-08-14 02:43:06 UTC
I've done two more tests.

First, with an external card reader, everything is nice with 2.6.23-rc3 (the card reader is seen, then the device appears when I plug a card). This kernel fails only with the integrated card reader of my laptop.

Second, I tried to boot 2.6.23-rc3 with the card plugged in the memory card reader, so the card would be seen when the card reader is detected by the kernel. There is a bunch of IO errors while trying to read the first partition table, and the card is still not usable. dmesg appended.
Comment 17 Christian Casteyde 2007-08-14 02:46:54 UTC
Created attachment 12380 [details]
dmesg for 2.6.23-rc3 with card plugged at boot time

Using fdisk after boot adds more errors, they are suppressed by the kernl, but these are still IO errors.

I can do any test needed of course.
Comment 18 Christian Casteyde 2007-08-14 02:50:50 UTC
Just to be precise, in the external reader test (see #16), I was not on the laptop but on a desktop PC with 2.6.23-rc3. Moreover, this PC is 32bit only, whereas the laptop runs 64 bits kernel.

The last test seems to indicate this is more than a race condition in device access at boot. It should have worked.
Comment 19 Alan Stern 2007-08-14 07:49:46 UTC
Calm down and stop running tests at random.  Let's start by seeing what happens when you boot 2.6.23-rc3 on the laptop without any card in the reader.  To get some useful information, you must enable CONFIG_USB_STORAGE_DEBUG.  Attach the dmesg log for the bootup.

Then insert a card in the reader and run the blockdev command, and attach the dmesg log for that.
Comment 20 Christian Casteyde 2007-08-14 14:44:23 UTC
No problem, I simply did tests I thought could be usefull, and I answered essentially to #4 and #5. I also noticed the device was seen earlier in the boot process, hence the dmesg output splitted before udev, after, and after plugging (no more info in it). And I thought the error message was due to the fact that the card was not plugged, so the last test.

I append the following dmesg as you asked for (2.6.23 only for now, if you intend to compare with 2.6.22 tell me):
- dmesg just before udev start,
- dmesg after udev start but before plugging the card,
- dmesg after pluggint the card,
- dmesg after blockdev /dev/sda
sorry, this will make 4 mails, but I split them to be sure to get everything, because STORAGE_DEBUG fills the dmesg buffer. The last one are partial I think, but I fixed the size to max for the buffer (17). I also added time stamps to correlate traces from the different logs - just in case this is usefull to you.
Comment 21 Christian Casteyde 2007-08-14 14:45:53 UTC
Created attachment 12387 [details]
Debug dmesg before udev start
Comment 22 Christian Casteyde 2007-08-14 14:46:41 UTC
Created attachment 12388 [details]
Debug dmesg before after udev, before plugging the card
Comment 23 Christian Casteyde 2007-08-14 14:47:39 UTC
Created attachment 12389 [details]
Debug dmesg before after plugging the card
Comment 24 Christian Casteyde 2007-08-14 14:49:23 UTC
Created attachment 12390 [details]
Debug dmesg after blockdev / rereadpt

In last two comments:
"before after" == "after" (copy/paste error)
Comment 25 Alan Stern 2007-08-15 08:14:54 UTC
That's interesting.  There is a clear series of error reports from the card reader.  If you can do the same experiment now with 2.6.22, it will be interesting to compare the results.

One more thing: While running these tests you should turn off HAL.  The daemon sends a bunch of requests to the card reader, which clutters up the log.  In fact, it might be a good idea to redo the log in #22 with HAL turned off, since some potentially useful information got overwritten in the buffer.

From what I've seen the card reader isn't working correctly.  It reports an error code (Medium error; Cannot read medium - unknown format) even when there is no card present.  And it doesn't report an error for TEST UNITY READY, which it should.  
Comment 26 Christian Casteyde 2007-08-16 13:55:41 UTC
I turned off HAL and dmesg logs are now readable. I kept time stamping however.
I post two dmesg logs, one for 2.6.22 and one for 2.6.23, with anotations indicating where the different actions were taken (boot, udev start, inserting card, and blockdev).
Comment 27 Christian Casteyde 2007-08-16 13:57:14 UTC
Created attachment 12407 [details]
dmesg for 2.6.22 with annotations but without HAL
Comment 28 Christian Casteyde 2007-08-16 13:58:43 UTC
Created attachment 12408 [details]
dmesg for 2.6.23 with annotations but without HAL

Note that an external USB key does works on this laptop with 2.6.23 (=> not a pure USB problem).
Comment 29 Alan Stern 2007-08-17 11:37:17 UTC
Created attachment 12431 [details]
Reduce number of READ CAPACITY retries

The dmesg buffer filling up in 2.6.23-rc3 is annoying.  This patch should prevent it.  Please apply it and then run the test one more time.
Comment 30 Christian Casteyde 2007-08-18 02:56:33 UTC
Created attachment 12434 [details]
dmesg for 2.6.23-rc3 with sd.c patched (READ_CAPACITY)

Doesn't seem to reduce the number of commands READ_CAPACITY issued indeed. So I checked it, the patch did apply correctly in the kernel sources.
This card reader is a multicard reader btw (MMC, SD, etc.), but I only use a SD card.
Comment 31 Alan Stern 2007-08-18 08:26:35 UTC
No, the patch did indeed reduce the number of READ CAPACITY commands considerably.  So in that sense the test succeeded.  However the results are a little baffling -- even though usb-storage sends exactly the same commands to the card reader in 2.6.22 and 2.6.23-rc3, the reader sends back different responses!

You can see this in the logs; the difference shows up when you run blockdev.  About 6 lines above the second TEST_UNIT_READY line, you'll see that the 2.6.22 log says: 

   -- code: 0x70, key: 0x6, ASC: 0x28, ASCQ: 0x0

(which is what it should say), whereas the 2.6.23-rc3 line says:

   -- code: 0x70, key: 0x3, ASC: 0x30, ASCQ: 0x1

Everything before that is the same.  This indicates that the change in behavior was caused by something outside the usb-storage driver.  A likely candidate is USB autosuspend -- 2.6.22 would not normally suspend a card reader but 2.6.23 would.  Perhaps your reader is buggy and can't handle being suspended.  It wouldn't be surprising; the lsusb data for the reader shows pretty clearly that the manufacturer didn't bother to put on any finishing touches and probably didn't bother to test it very well.

I'll attach a patch to prevent the card reader from being autosuspended.
Comment 32 Alan Stern 2007-08-18 08:29:17 UTC
Created attachment 12438 [details]
Prevent the SGS Thomson card reader from autosuspending

This patch is against 2.6.23-rc1.  If you have trouble applying it to -rc3, you ought to be able to edit the source file by hand and paste in the extra text.
Comment 33 Christian Casteyde 2007-08-19 07:51:11 UTC
With this patch, all is OK.
I append the resulting dmesg for the record.
Thanks a lot
Comment 34 Christian Casteyde 2007-08-19 07:52:37 UTC
Created attachment 12443 [details]
dmesg for 2.6.23+patch no autosuspend = OK
Comment 35 Alan Stern 2007-08-19 07:58:23 UTC
Just out of curiosity, what happens if you change the patch?  In the line added for the SGS Thomson reader, try changing USB_QUIRK_NO_AUTOSUSPEND to USB_QUIRK_RESET_RESUME.  I'd like to know which version of the patch to submit.
Comment 36 Alan Stern 2007-09-11 11:54:23 UTC
The patch has been accepted, and it should appear in 2.6.23.  Closing the bug.