Bug 5010

Created attachment 5525 [details]
System information (outputs of lsmod, dmesg, etc.) relevant to the bug

It will help a lot if you turn on USB verbose debugging (CONFIG_USB_DEBUG) and
USB Mass Storage verbose debugging (CONFIG_USB_STORAGE_DEBUG) in the kernel
configuration.  It might also help if you upgrade to the current 2.6.13-rc release.

(BTW, there was no need to send three separate copies of your dmesg output,
since each copy contained everything that was in the previous copy.)

Created attachment 5698 [details]
Relevant part of /var/log/messages, same kernel configuration as before, just with usb verbose debug and usb mass storage debug turned on

Created attachment 5699 [details]
Output of dmesg after the second plugging of the USB device

As far as I can see, the only difference between the first plug-in and the
second is that the first one has a 2-second delay during which the hotplug
system loads the usb-storage driver.  It could be that the drive is defective
and won't work properly without this delay.

Just as a quick test, try doing "rmmod usb-storage" after unplugging the drive
and before replugging it.  It's enough to post the /var/log/messages extract,
since it contains pretty much everything that was in your dmesg output.  If you
would insert a disc (say, an audio CD) in the drive before running your test,
that ought to reduce the total number of messages in the log.

Have just tried the quick test suggested by Alan Stern.
It does not help :-((

An augmentation to my previous comment:
"rmmod usb-storage" works only in the situation where the USB drive was
responding when plugged in.
If I unplug the drive in the situation where it does not respond, rmmod just says:
# rmmod usb-storage
ERROR: Module usb_storage is in use

I do not have other usb-storage devices plugged in at the moment.

Another way of testing this occurred to me.  After booting, before you plug in
the DVD device for the first time, do "modprobe usb-storage".  That will
eliminate the hotplug delay.  The question is, will the device still work? 
Remember to attach the system log showing what happens (and put a disc in the
drive before starting the test).

Also, 

Created attachment 5711 [details]
Log messages for the test described below

As suggested by Alan, I have just tried the following test:
1. booted
2. entered the command "modprobe usb-storage". According to "lsmod" the module
was properly loaded
3. plugged in the USB device, with a disc put in. It did *not* respond.
"eject sr0" resulted in "Cannot open the device /dev/sr0".

Created attachment 5712 [details]
Log messages, see comment for details

I have just tried again whether the drive would respond just after booting.
I was really surprised: now the drive refused to respond just after first
plugging. The only explanation I have is that there must be race conditions or
timing issues in modules. Otherwise the error would be deterministic.

A more likely explanation is that there is a race condition or timing error in
the drive itself.  Or else the drive is just broken.

From what you've said, it's not fully clear exactly how you've been running your
tests.  Try doing this:  With the USB cable unplugged, turn on the drive and
leave it on for 30 seconds or so (until it has finished its initialization,
reading the disc's table of contents, and so on).  Then plug in the USB cable.

Another thing to try.  Edit /etc/modprobe.conf and add a line saying:

    options usb-storage delay_use=30

Then make sure usb-storage is unloaded, and run your test again.

Created attachment 5730 [details]
Log messages with "options usb-storage delay_use=30"

As the drive cannot load disk without being plugged in, the test cannot be
carried out in exactly the suggested sequence.

I performed the following test sequence:
1. booted
1.5 added the line "options usb-storage delay_use=30" to /etc/modprobe.conf
2. plugged the drive in.
3. loaded a disk. I did not try "eject" at this step, I loaded the disk just by
pressing the button on the drive
4. unplugged the drive
5. rebooted with the drive unplugged. After reboot I had an unplugged drive
with a disc inside and a kernel with usb-storage unloaded. The drive does not
perform any self-initialization as long as it is unplugged
6. plugged the drive in. It did *not* respond to "eject", just after the first
plugging. ("eject" says "cannot open /dev/sr0")
7. Drive initialization attempts took 5 to 10 minutes (hearable movements of
mechanical parts). After these attempts have been finished, "eject" does not
terminate any more, it just hangs.

Created attachment 5735 [details]
Delay Get-Max-LUN request

No initialization until the USB cable is plugged in?  I was afraid of that.

Okay, here's a patch that will cause the usb-storage driver to delay issuing
the Get-Max-LUN request, which is the first thing it sends to the device. 
Currently that request gets sent immediately, and it has been failing.	(You
can see those failures near the start of your logs.)  I'm guessing that failure
of the Get-Max-LUN causes the later failures somehow.  With this patch, maybe
nothing will fail.

So apply the patch, rebuild the usb-storage driver, and run your test again.

Created attachment 5736 [details]
drivers/usb/storage/usb.c

Sorry, I cannot apply the patch:
# patch --dry-run usb.c  ~/usb_patch.c
patching file usb.c
Hunk #1 FAILED at 765.
Hunk #2 FAILED at 902.
2 out of 2 hunks FAILED -- saving rejects to file usb.c.rej

Created attachment 5737 [details]
Delay Get-Max-LUN request

I thought you were using kernel 2.6.11, but apparently not.  This patch should
apply against your source file okay.

Created attachment 5738 [details]
/var/log/messages after applying the patch

The patch does work.
Thank you very much indeed!
You are the best! ;-)

P.S. I attached the log messages for you to see what happens.
P.P.S. As for for my kernel, it's 2.6.11.4-21.7 from the SuSE distribution, not
from kernel.org

Created attachment 5739 [details]
/var/log/messages after applying the patch

Something went wrong with the previous attachment.
Next try...

That's the first time I've seen this particular problem.  I'll submit the patch
for inclusion in the kernel.  It won't be in time for 2.6.13, but maybe it will
appear in 2.6.14.

You should go ahead and turn off the USB Mass Storage verbose debugging, and you
can remove the usb-storage options line from /etc/modprobe.conf.  The default
delay is 5 seconds, which ought to be enough for your drive.  If it isn't, you
can put the options line back in, with some value for delay_use between 5 and 30
-- try different numbers until you find one that works.

Let me know if everything continues to work okay without the debugging or the
modprobe option.  If it does, you can go ahead and close out this bug.

Created attachment 5761 [details]
/var/log/messages with several USB mass storage devices

The patch works really fine as long as the DVD-drive is the only USB mass
storage.
Today I (unintentionally) performed a harder test:

1. Plugged in the iPod
2. Mounted the iPod
3. Copied some mp3 files onto the iPod
4. started xmms directly on the iPod file system
5. Plugged in the DVD-drive
6. after the DVD-drive was initialized, the iPod file system gets unmounted due
to USB errors. It cannot be remounted:
"mount /USB"
results in
"/dev/sda1 is not a valid block device"
Unplugging and replugging of the iPod does not solve the problem.

This is a separate problem.  You should close this bug and start a new bug
report.  When you do, include a description of what happens if you just try
plugging in the iPod while using the DVD drive.

The patch works fine even without the "delay"-option in modprobe.conf and with
verbose debugging turned off.