Re: [edk2-devel] [PATCH] MdeModulePkg/UsbBusDxe: Rebuild the description table after Reset Device

["Jeremy Linton" <jeremy.linton@arm.com>]

Hi,

On 4/26/20 8:36 PM, Wu, Hao A via groups.io wrote:
>> -----Original Message-----
>> From: Jiang, Guomin
>> Sent: Sunday, April 26, 2020 9:05 PM
>> To: Wu, Hao A; devel@edk2.groups.io
>> Cc: Wang, Jian J; Ni, Ray
>> Subject: RE: [edk2-devel] [PATCH] MdeModulePkg/UsbBusDxe: Rebuild the
>> description table after Reset Device
>>
>> Add comment inline.
>>
>>> -----Original Message-----
>>> From: Wu, Hao A <hao.a.wu@intel.com>
>>> Sent: Sunday, April 26, 2020 4:04 PM
>>> To: Jiang, Guomin <guomin.jiang@intel.com>; devel@edk2.groups.io
>>> Cc: Wang, Jian J <jian.j.wang@intel.com>; Ni, Ray <ray.ni@intel.com>
>>> Subject: RE: [edk2-devel] [PATCH] MdeModulePkg/UsbBusDxe: Rebuild the
>>> description table after Reset Device
>>>
>>>> -----Original Message-----
>>>> From: Jiang, Guomin
>>>> Sent: Sunday, April 26, 2020 2:44 PM
>>>> To: Wu, Hao A; devel@edk2.groups.io
>>>> Cc: Wang, Jian J; Ni, Ray
>>>> Subject: RE: [edk2-devel] [PATCH] MdeModulePkg/UsbBusDxe: Rebuild
>>> the
>>>> description table after Reset Device
>>>>
>>>> Hi Hao,
>>>>
>>>> Add comments inline.
>>>>
>>>>> -----Original Message-----
>>>>> From: Wu, Hao A <hao.a.wu@intel.com>
>>>>> Sent: Sunday, April 26, 2020 1:12 PM
>>>>> To: devel@edk2.groups.io; Wu, Hao A <hao.a.wu@intel.com>; Jiang,
>>>> Guomin
>>>>> <guomin.jiang@intel.com>
>>>>> Cc: Wang, Jian J <jian.j.wang@intel.com>; Ni, Ray <ray.ni@intel.com>
>>>>> Subject: RE: [edk2-devel] [PATCH] MdeModulePkg/UsbBusDxe: Rebuild
>>>>> the description table after Reset Device
>>>>>
>>>>>> -----Original Message-----
>>>>>> From: devel@edk2.groups.io [mailto:devel@edk2.groups.io] On
>> Behalf
>>>> Of
>>>>>> Wu, Hao A
>>>>>> Sent: Sunday, April 26, 2020 1:10 PM
>>>>>> To: Jiang, Guomin; devel@edk2.groups.io
>>>>>> Cc: Wang, Jian J; Ni, Ray
>>>>>> Subject: Re: [edk2-devel] [PATCH] MdeModulePkg/UsbBusDxe:
>>> Rebuild
>>>>> the
>>>>>> description table after Reset Device
>>>>>>
>>>>>>> -----Original Message-----
>>>>>>> From: Jiang, Guomin
>>>>>>> Sent: Saturday, April 25, 2020 9:36 AM
>>>>>>> To: devel@edk2.groups.io
>>>>>>> Cc: Wang, Jian J; Wu, Hao A; Ni, Ray
>>>>>>> Subject: [PATCH] MdeModulePkg/UsbBusDxe: Rebuild the
>>> description
>>>>>>> table after Reset Device
>>>>>>>
>>>>>>> REF: https://bugzilla.tianocore.org/show_bug.cgi?id=2694
>>>>>>>
>>>>>>> When the USB fail and then Reset Device, it should rebuild
>> description.
>>>>>>>
>>>>>>> Signed-off-by: Guomin Jiang <guomin.jiang@intel.com>
>>>>>>> Cc: Jian J Wang <jian.j.wang@intel.com>
>>>>>>> Cc: Hao A Wu <hao.a.wu@intel.com>
>>>>>>> Cc: Ray Ni <ray.ni@intel.com>
>>>>>>> ---
>>>>>>>   MdeModulePkg/Bus/Usb/UsbBusDxe/UsbBus.c | 5 +++++
>>>>>>>   1 file changed, 5 insertions(+)
>>>>>>>
>>>>>>> diff --git a/MdeModulePkg/Bus/Usb/UsbBusDxe/UsbBus.c
>>>>>>> b/MdeModulePkg/Bus/Usb/UsbBusDxe/UsbBus.c
>>>>>>> index 4b4915c019..9f2d2cc87f 100644
>>>>>>> --- a/MdeModulePkg/Bus/Usb/UsbBusDxe/UsbBus.c
>>>>>>> +++ b/MdeModulePkg/Bus/Usb/UsbBusDxe/UsbBus.c
>>>>>>> @@ -869,6 +869,11 @@ UsbIoPortReset (
>>>>>>>
>>>>>>>
>>>>>>>     DEBUG (( EFI_D_INFO, "UsbIoPortReset: device is now
>> ADDRESSED
>>>>>>> at %d\n", Dev->Address));
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> +  //
>>>>>>>
>>>>>>> +  // The description will be invalid after reset, should rebuild it as
>> well.
>>>>>>>
>>>>>>> +  //
>>>>>>>
>>>>>>> +  UsbBuildDescTable (Dev);
>>>>>>
>>>>>>
>>>>>> Hello Guomin,
>>>>>>
>>>>>> Thanks for the proposed patch.
>>>>>>
>>>>>> Could you help to explain in more detail for the above fix with
>>>>>> regard to the transfer ring not being set properly in the XHCI driver?
>>> Thanks.
>>>>
>>>> When I debug, I dump the below data structure and found that before
>>>> UsbMassReset, the corresponding slot transfer ring is normal and
>>>> invalid after UsbMassReset.
>>>> USB_DEV_CONTEXT = 0x148
>>>>   +0x0 Enabled
>>>>   +0x1 SlotId
>>>>   +0x4 RouteString
>>>>   +0x8 ParentRouteString
>>>>   +0xC XhciDevAddr
>>>>   +0xD BusDevAddr
>>>>   +0x10 InputContext
>>>>   +0x18 OutputContext
>>>>   +0x20 EndpointTransferRing[31]
>>>>   +0x118 DevDesc
>>>>   +0x130 ConfDesc
>>>>   +0x138 ActiveConfiguration
>>>>   +0x140 ActiveAlternateSetting
>>>>
>>>> Before UsbMassReset
>>>> 000002D0:                                            -01 01 00 00 00 00 10 10
>>>> 000002E0: 00 00 00 00 01 01 00 00-80 02 FA 06 00 00 00 00
>>>> 000002F0: C0 16 FA 06 00 00 00 00-98 27 FC 06 00 00 00 00
>>>> 00000300: 00 00 00 00 00 00 00 00-98 26 FC 06 00 00 00 00
>>>> 00000310: 98 BE F9 06 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 00000320: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 00000330: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 00000340: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 00000350: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 00000360: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 00000370: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 00000380: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 00000390: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 000003A0: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 000003B0: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 000003C0: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 000003D0: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 000003E0: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 000003F0: 12 01 00 03 00 00 00 09-F4 46 01 00 00 00 01 02
>>>> 00000400: 03 01 00 00 00 00 00 00-98 CD F9 06 00 00 00 00
>>>> 00000410: 01 00 00 00 00 00 00 00-18 24 FC 06 00 00 00 00
>>>>
>>>> After UsbMassReset
>>>> 000002D0:                                           -01 01 00 00 00 00 10 10
>>>> 000002E0: 00 00 00 00 01 01 00 00-80 02 FA 06 00 00 00 00
>>>> 000002F0: C0 16 FA 06 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 00000300: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 00000310: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 00000320: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 00000330: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 00000340: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 00000350: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 00000360: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 00000370: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 00000380: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 00000390: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 000003A0: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 000003B0: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 000003C0: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 000003D0: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 000003E0: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 000003F0: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 00000400: 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>> 00000410: 01 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00
>>>>
>>>> After Reset Finished, it will try to get data again by sending command
>>>> to Usb Mass Device and it will use USB_DEV_CONTEXT.
>>> EndpointTransferRing[4].
>>>> But it haven't been initialized after reset, and ASSERT will trigger
>>>> when access the USB_DEV_CONTEXT. EndpointTransferRing and will
>> show
>>>> ASSERT
>>>>
>>>
>> c:\users\guominji\dcg10nm\edk2\MdeModulePkg\Bus\Pci\XhciDxe\XhciSch
>>> e
>>>> d.c(1909): TrsRing != ((void *) 0)
>>>>
>>>> The EndpointTranferRing should be initialized by UsbBuildDescTable()
>>>> but seem that it is omitted in Reset branch, so I add it.
>>>
>>>
>>> Sorry Guomin, I still do not fully understand the link between calling the
>>> UsbBuildDescTable() in UsbBusDxe and the re-initialization of the
>>> 'EndpointTranferRing' in the XhciDxe. Could you help to provide more detail?
>>
>> I am sorry that make confusion to you, I will explain it in detail now.
>> 1. The critical call flow as below
>> UsbMassReset()
>> --> UsbMass->Transport->Reset() == UsbBotResetDevice()
>>       --> UsbBot->UsbIo->UsbPortReset() == UsbIoPortReset()
>>             --> UsbIf->Device->ParentIf->HubApi->ResetPort() ==
>> UsbRootHubResetPort()
>>                   --> UsbHcGetRootHubPortStatus()
>>                         --> UsbBus->Usb2Hc-GetRootHubPortStatus() ==
>> XhcGetRootHubPortStatus()
>>                               --> XhcPollPortStatusChange()
>>                                    --> XhcDisableSlotCmd() or XhcDisableSlotCmd64() [Very
>> very critical routine 1]
>>                                    --> XhcInitializeDeviceSlot() or XhcInitializeDeviceSlot64()
>> [Very very critical routine 2]
>>             --> UsbSetAddress()
>>             --> UsbSetConfig()
>>                   -->  UsbBus->Usb2Hc->ControlTransfer() == XhcControlTransfer()
>>                          --> XhcSetConfigCmd() or XhcSetConfigCmd64() [Very very
>> critical routine 3]

I guess the key here is that the code path for USB_REQ_SET_CONFIG in 
XhcControlTransfer is being called but there is a loop for each 
configuration the device supports. Those config descriptors are "cached" 
in the XHCI driver from a previous call to XhcControlTransfer() 
requesting the device descriptors. If that data is missing, then 
XhcSetConfigCmd() never gets called for an endpoint and the CmdRing 
never gets setup causing XhcSyncTrsRing() to de-reference a null ptr.

If you look at the patch I posted, I wrapped all this in the if 
ActiveConfig !=NULL check, because presumably AFAIK, its possible you 
get the reset inside of the initial enumeration (well actually earlier 
than I'm seeing it AFAIK). So, I'm not an expert on this code path so it 
might be worth considering the difference in the two patches.

The config I consistently reproduced this on:

rpi4->XHCI->USB3 hub->JMICRON 5 bay USB JBOD.

The JBOD is 05/2400'ing one of the commands in the mass storage driver 
(that's a different problem) which causes it to attempt the port reset. 
Which causes instant boot death. With my patch it retries the "illegal 
command" a _LOT_ when it should really be giving up immediately. I have 
a patch for that in my pocket too, but this seemed the more 
general/problematic case since it should be happening a lot on XHCI 
attached devices taking errors (and in fact I think i've seen it with 
USB CDROMS/etc in the past).




>>
>> There are three very very critical routine,
>> 1. XhcDisableSlotCmd() or XhcDisableSlotCmd64() will disable the slot context
>> and free the allocated memory.
>> 2. XhcInitializeDeviceSlot() or XhcInitializeDeviceSlot() will initialize the basic
>> control and slot endpoint transfer ring.
>> 3. XhcSetConfigCmd() or XhcSetConfigCmd64() will configure the other
>> transfer ring. It  depend on Xhc-
>>> UsbDevContext[Slot].DevDesc.NumConfigurations, unfortunately, the
>> DevDesc haven't benn initialized by UsbBuildDescTable and it is 0. So
>> XhcSetConfigCmd() or XhcSetConfigCmd64() haven't run.
>>
>> After run below 3 critical routine, the device is initialize but
>> EndpointTransferRing of Input and Output haven't been initialized and still
>> keep NULL.
>>
>> When UsbMassReadBlocks, it will use uninitialized EndpointTransferRing and
>> will ASSERT.
> 
> 
> Thanks a lot Guomin,
> 
> Now I understand the reason behind for the proposed fix.
> 
> I would suggest to add an abstract of the above analysis in the commit message,
> such information will be helpful for others who might work on USB/Xhci in the
> future.
> 
> 
>>
>>> Another thing I found (if current proposed fix is a proper solution) is that in
>>> UsbBuildDescTable() , several memory allocations will be made to store the
>>> device descriptor/config descriptor. Could you help to double check if their
>>> old values are properly freed in order to avoid memory leak?
>>>
>>
>> I will investigate it and give you feedback.
> 
> 
> Thanks for this.
> 
> Best Regards,
> Hao Wu
> 
> 
>>
>>> Best Regards,
>>> Hao Wu
>>>
>>>
>>>>
>>>>>>
>>>>>> Also, judging from the function description comments in
>>>>> UsbBuildDescTable():
>>>>>> |>  /**
>>>>>> |>    Build the whole array of descriptors. This function must
>>>>>> |>    be called after UsbGetMaxPacketSize0 returns the max packet
>>>>>> |>    size correctly for endpoint 0.
>>>>>> |>  ...
>>>>>> |>  **/
>>>>>> |>  EFI_STATUS
>>>>>> |>  UsbBuildDescTable (
>>>>>> |>    IN USB_DEVICE           *UsbDev
>>>>>> |>    )
>>>>>>
>>>>>> Does function UsbGetMaxPacketSize0() need to be called before
>>>>>> UsbBuildDescTable() in the proposed fix?
>>>>
>>>> I ignored it and will double check it.
>>>>
>>>>>
>>>>>
>>>>> One more thing, could you help to add the information for what tests
>>>>> have been done for the proposed patch as well?
>>>>>
>>>>> Thanks in advance.
>>>>>
>>>>
>>>> Have test OVMF and test pass, detail as below I use qemu-w64-2020020,
>>>> you should install it first and add it to PATH environment, the
>>>> procedure as below 1. Import the test patch from
>>>> https://bugzilla.tianocore.org/attachment.cgi?id=508
>>>> 2. type ```build -p OvmfPkg\OvmfPkgX64.dsc -b DEBUG -a X64``` to
>>>> generate OVMF.fd 3. type ```qemu-img create file.img 1G``` to create
>>>> test image.
>>>> 4. type ```qemu-system-x86_64 -bios OVMF.fd -drive
>>>> if=none,id=stick,file=file.img -device nec-usb-xhci,id=xhci, -device
>>>> usb- storage,bus=xhci.0,drive=stick -global isa-debugcon.iobase=0x402
>>>> - debugcon file:xhci.log``` 5. you will see hang currently and will
>>>> see ASSERT when check xhci.log.
>>>> 6. import proposal patch, the symptom disappear.
>>>>
>>>>>
>>>>>>
>>>>>> Best Regards,
>>>>>> Hao Wu
>>>>>>
>>>>>>
>>>>>>>
>>>>>>> +
>>>>>>>
>>>>>>>     //
>>>>>>>
>>>>>>>     // Reset the current active configure, after this device
>>>>>>>
>>>>>>>     // is in CONFIGURED state.
>>>>>>>
>>>>>>> --
>>>>>>> 2.25.1.windows.1
>>>>>>
>>>>>>
>>>>>>
>>>>>
>>>>
>>>
>>
> 
> 
> 
>