Re: Bug caused by 53965c79c2db (USB: Fix device driver race)

["M. Vefa Bicakci" <m.v.b@runbox.com>]

On 19/10/2020 13.40, Alan Stern wrote:
> On Mon, Oct 19, 2020 at 09:36:00AM +0000, Pany wrote:
>> On Sat, Oct 17, 2020 at 8:02 PM Alan Stern <stern@rowland.harvard.edu> wrote:
>>>
>>> On Sat, Oct 17, 2020 at 04:07:11PM +0000, Pany wrote:
>>>> Hi,
>>>>
>>>> I installed fedora 32 into an SD card, with which I booted my Macbook.
>>>> It had worked well before, until I upgraded the kernel from 5.8.5 to
>>>> 5.8.6 [1].
>>>>
>>>> With kernel-5.8.6-200.fc32.x86_64.rpm [2] installed, the boot process
>>>> would be stuck at "A start job is running for
>>>> /dev/mapper/fedora_localhost_--live-home (<time> / no limit)" (See the
>>>> photo of screen [3]).
>>>>
>>>> By appending "systemd.debug-shell=1" to the kernel cmdline, I saved
>>>> the journal [4].
>>>>
>>>> This issue has been bisected to commit
>>>> 53965c79c2dbdc898ffc7fdbab37e920594f5e14 ("USB: Fix device driver
>>>> race")
>>>>
>>>> If I revert this commit, the kernel 5.8.6 would boot successfully.
>>>
>>> This should have been fixed in 5.8.14 or 5.8.15 (5.8.14 was released on
>>> the same day that the fix was installed; I'm not sure which came first).
>>> At any rate it certainly should work with the most recent 5.8.y kernel.
>>>
>>> Alan Stern
>>
>> I tried, but neither 5.8.14 nor 5.8.15 worked for me.
> 
> Hmmm.  Looking at the system log you captured, it appears that the
> problem the SD card reader's driver getting reprobed incorrectly.  The
> details aren't clear, but the log shows the device getting probed twice,
> once as sdb and once as sdc.  If the system tried to mount one of the
> sdb partitions as the root, and then sdb disappeared, that could explain
> what you see.
> 
> I don't know why this is happening.  But you can try adding some
> debugging messages of your own.  In drivers/usb/core/driver.c, the
> routine __usb_bus_reprobe_drivers() should never reach the line that
> calls device_reprobe() unless the USBIP or apple-mfi-fastcharge driver
> is installed -- and neither of those should be involved with the card
> reader device.  You can add a line saying:
> 
> 	dev_info(dev, "new driver %s\n", new_udriver->name);
> 
> at that point and see what it produces in the log.

Hello all,

Sorry for my lateness!

I reviewed Pany's logs, and the issue appears to be related to the
automatic loading of the apple-mfi-fastcharge USB driver, which triggers
a re-probe of the SD card reader, as pointed out earlier.

This happens because the id_table of the aforementioned USB driver
(mfi_fc_id_table) matches all USB products manufactured by Apple:

  35 static const struct usb_device_id mfi_fc_id_table[] = {
  36         { .idVendor = APPLE_VENDOR_ID,
  37           .match_flags = USB_DEVICE_ID_MATCH_VENDOR },
  38         {},
  39 };
  ...
218 static struct usb_device_driver mfi_fc_driver = {
219         .name =         "apple-mfi-fastcharge",
220         .probe =        mfi_fc_probe,
221         .disconnect =   mfi_fc_disconnect,
222         .id_table =     mfi_fc_id_table,
223         .generic_subclass = 1,
224 };


... and Pany's system has multiple USB devices manufactured by Apple
(including the SD card reader), with the vendor code 0x05ac, which is
the value included by the id_table of the apple-mfi-fastcharge driver:

Sep 29 15:22:48 fedora.local kernel: usb 2-3: new SuperSpeed Gen 1 USB device number 2 using xhci_hcd
Sep 29 15:22:48 fedora.local kernel: usb 2-3: New USB device found, idVendor=05ac, idProduct=8406, bcdDevice= 8.20
Sep 29 15:22:48 fedora.local kernel: usb 2-3: New USB device strings: Mfr=3, Product=4, SerialNumber=5
Sep 29 15:22:48 fedora.local kernel: usb 2-3: Product: Card Reader
Sep 29 15:22:48 fedora.local kernel: usb 2-3: Manufacturer: Apple
...
Sep 29 15:22:48 fedora.local kernel: usb 1-5: new full-speed USB device number 3 using xhci_hcd
Sep 29 15:22:48 fedora.local kernel: usb 1-5: New USB device found, idVendor=05ac, idProduct=0273, bcdDevice= 6.22
Sep 29 15:22:48 fedora.local kernel: usb 1-5: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Sep 29 15:22:48 fedora.local kernel: usb 1-5: Product: Apple Internal Keyboard / Trackpad
Sep 29 15:22:48 fedora.local kernel: usb 1-5: Manufacturer: Apple Inc.
...

One way to fix this issue would be to implement a match function in the
apple-mfi-fastcharge driver, possibly instead of an id_table, so that it
does not match devices that it cannot bind to. This may require other
changes in the USB core that I cannot fathom at the moment.

Pany, in the mean-time, could you add the following string to your kernel's
command line (i.e., via GRUB, or the actual boot-loader that you use) and
let us know whether it helps to *work around* this issue with the latest
versions of 5.8.y kernels?

	module_blacklist=apple-mfi-fastcharge

To emphasize, I am only suggesting this as a work-around, not as an actual
solution.

My time is a bit limited due to having restarted full-time employment,
but I can work on this issue during the weekend.

Thanks!

Vefa