linux-kernel - Re: [PATCH v2 1/2] usb: dwc3: Not set DWC3_EP_END_TRANSFER

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives
Hash Suite for Android: free password hash cracker in your pocket
[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <e165c644-4ad0-b103-4f8b-2d3bc1b211f1@codeaurora.org>
Date:   Mon, 28 Feb 2022 14:53:33 -0800
From:   Wesley Cheng <wcheng@...eaurora.org>
To:     Thinh Nguyen <Thinh.Nguyen@...opsys.com>,
        Wesley Cheng <quic_wcheng@...cinc.com>,
        Jung Daehwan <dh10.jung@...sung.com>
Cc:     Felipe Balbi <balbi@...nel.org>,
        Greg Kroah-Hartman <gregkh@...uxfoundation.org>,
        "linux-usb@...r.kernel.org" <linux-usb@...r.kernel.org>,
        open list <linux-kernel@...r.kernel.org>,
        "quic_jackp@...cinc.com" <quic_jackp@...cinc.com>
Subject: Re: [PATCH v2 1/2] usb: dwc3: Not set DWC3_EP_END_TRANSFER_PENDING in
 ep cmd fails

Hi Thinh,

On 2/24/2022 5:44 PM, Thinh Nguyen wrote:
> Wesley Cheng wrote:
>> Hi Thinh,
>>
>> On 2/24/2022 5:26 PM, Thinh Nguyen wrote:
>>> Hi Wesley,
>>>
>>> Wesley Cheng wrote:
>>>> Hi Thinh,
>>>>
>>>> On 2/22/2022 6:59 PM, Thinh Nguyen wrote:
>>>>> Hi Wesley,
>>>>>
>>>
>>> <snip>
>>>
>>>>>
>>>>> Can you provide a full trace?
>>>>>
>>>> Sorry for doing this, but we didn't have a way to share the file
>>>> directly, so I have to paste the trace below. :/
>>>>
>>>>> Btw, when you experiment with increasing the timeout to 10 seconds, did
>>>>> you use the mdelay() in each loop? The delta time for End Transfer
>>>>> timeout here seems very small.
>>>>>
>>>> This particular run did not modify the timeout for the cmd status polling.
>>>>
>>>> Is that something that you want to try?  Not pertaining to this dequeue
>>>> situation, during the pullup disable path debug, I noticed that as long
>>>> as there was a pending EP0 SETUP packet (not data/status) cached in the
>>>> controller, it would also have endxfer timeouts on non-control EPs.  We
>>>> were able to capture a bus sniffer log + ftrace, and it showed that at
>>>> the point of the error, the lecroy/bus log saw a SETUP token ACK'ed,
>>>> while on the ftrace, there were endxfer timeouts for all non-control EPs
>>>> (due to the dwc3_gadget_stop_active_transfers() call)
>>>>
>>>> Thanks
>>>> Wesley
>>>>
>>>> TRACE
>>>> ---------------------------------------------------------------------
>>>>
>>>
>>> <snip>
>>>
>>>> [ 1023.912550050       0x4af666fd2]   dbg_trace_log_ctrl: Clear Endpoint
>>>> Feature(Halt ep4in)
>>>> [ 1023.912934738       0x4af668cab]   dbg_send_ep_cmd: ep0out: cmd 'Set
>>>> Stall' [404] params 00000000 00000000 00000000 --> status: Successful
>>>> [ 1023.913361561       0x4af66acae]   dbg_send_ep_cmd: ep0out: cmd
>>>> 'Start Transfer' [406] params 00000000 efffa000 00000000 --> status:
>>>> Successful
>>>> [ 1024.336480573       0x4afe2a29b]   dbg_trace_log_ctrl: Clear Endpoint
>>>> Feature(Halt ep5in)
>>>> [ 1024.336855573       0x4afe2bebc]   dbg_send_ep_cmd: ep5in: cmd 'Clear
>>>> Stall' [405] params 00000000 00000000 00000000 --> status: Successful
>>>> [ 1024.337264531       0x4afe2dd68]   dbg_send_ep_cmd: ep0in: cmd 'Start
>>>> Transfer' [406] params 00000000 efffa000 00000000 --> status: Successful
>>>> [ 1024.351910156       0x4afe727d4]   dbg_send_ep_cmd: ep0out: cmd
>>>> 'Start Transfer' [406] params 00000000 efffa000 00000000 --> status:
>>>> Successful
>>>> [ 1024.363139896       0x4afea720f]   dbg_trace_log_ctrl: Clear Endpoint
>>>> Feature(Halt ep4in)
>>>> [ 1024.363898281       0x4afeaaaf0]   dbg_send_ep_cmd: ep0out: cmd 'Set
>>>> Stall' [404] params 00000000 00000000 00000000 --> status: Successful
>>>> [ 1024.364734010       0x4afeae99e]   dbg_send_ep_cmd: ep0out: cmd
>>>> 'Start Transfer' [406] params 00000000 efffa000 00000000 --> status:
>>>> Successful
>>>> [ 1024.776173803       0x4b063739a]   dbg_trace_log_ctrl: Clear Endpoint
>>>> Feature(Halt ep5in)
>>>> [ 1024.776907188       0x4b063aa9b]   dbg_send_ep_cmd: ep5in: cmd 'Clear
>>>> Stall' [405] params 00000000 00000000 00000000 --> status: Successful
>>>> [ 1024.777646147       0x4b063e208]   dbg_send_ep_cmd: ep0in: cmd 'Start
>>>> Transfer' [406] params 00000000 efffa000 00000000 --> status: Successful
>>>> [ 1024.788641980       0x4b0671ab8]   dbg_send_ep_cmd: ep0out: cmd
>>>> 'Start Transfer' [406] params 00000000 efffa000 00000000 --> status:
>>>> Successful
>>>> [ 1024.799682397       0x4b06a56bf]   dbg_trace_log_ctrl: Clear Endpoint
>>>> Feature(Halt ep4in)
>>>> [ 1024.800442605       0x4b06a8fc3]   dbg_send_ep_cmd: ep0out: cmd 'Set
>>>> Stall' [404] params 00000000 00000000 00000000 --> status: Successful
>>>> [ 1024.801184584       0x4b06ac769]   dbg_send_ep_cmd: ep0out: cmd
>>>> 'Start Transfer' [406] params 00000000 efffa000 00000000 --> status:
>>>> Successful
>>>> [ 1025.222173752       0x4b0e61d99]   dbg_trace_log_ctrl: Clear Endpoint
>>>> Feature(Halt ep5in)
>>>> [ 1025.222991669       0x4b0e65af1]   dbg_send_ep_cmd: ep5in: cmd 'Clear
>>>> Stall' [405] params 00000000 00000000 00000000 --> status: Successful
>>>> [ 1025.223850731       0x4b0e69b5f]   dbg_send_ep_cmd: ep0in: cmd 'Start
>>>> Transfer' [406] params 00000000 efffa000 00000000 --> status: Successful
>>>> [ 1025.239023492       0x4b0eb0d54]   dbg_send_ep_cmd: ep0out: cmd
>>>> 'Start Transfer' [406] params 00000000 efffa000 00000000 --> status:
>>>> Successful
>>>> [ 1025.248963179       0x4b0edf6ce]   dbg_trace_log_ctrl: Clear Endpoint
>>>> Feature(Halt ep4in)
>>>> [ 1025.249709846       0x4b0ee2ecd]   dbg_send_ep_cmd: ep0out: cmd 'Set
>>>> Stall' [404] params 00000000 00000000 00000000 --> status: Successful
>>>> [ 1025.250533440       0x4b0ee6c93]   dbg_send_ep_cmd: ep0out: cmd
>>>> 'Start Transfer' [406] params 00000000 efffa000 00000000 --> status:
>>>> Successful
>>>> [ 1025.667084535       0x4b16875e7]   dbg_trace_log_ctrl: Clear Endpoint
>>>> Feature(Halt ep5in)
>>>> [ 1025.667827764       0x4b168ada6]   dbg_send_ep_cmd: ep5in: cmd 'Clear
>>>> Stall' [405] params 00000000 00000000 00000000 --> status: Successful
>>>> [ 1025.668635993       0x4b168ea44]   dbg_send_ep_cmd: ep0in: cmd 'Start
>>>> Transfer' [406] params 00000000 efffa000 00000000 --> status: Successful
>>>> [ 1025.674777764       0x4b16ab6e7]   dbg_send_ep_cmd: ep0out: cmd
>>>> 'Start Transfer' [406] params 00000000 efffa000 00000000 --> status:
>>>> Successful
>>>> [ 1025.684733597       0x4b16da197]   dbg_trace_log_ctrl: Clear Endpoint
>>>> Feature(Halt ep4in)
>>>> [ 1025.685336150       0x4b16dcec7]   dbg_send_ep_cmd: ep0out: cmd 'Set
>>>> Stall' [404] params 00000000 00000000 00000000 --> status: Successful
>>>> [ 1025.686112608       0x4b16e0904]   dbg_send_ep_cmd: ep0out: cmd
>>>> 'Start Transfer' [406] params 00000000 efffa000 00000000 --> status:
>>>> Successful
>>>> [ 1025.698842347       0x4b171c3bf]   dbg_send_ep_cmd: ep0out: cmd 'Set
>>>> Stall' [404] params 00000000 00000000 00000000 --> status: Successful
>>>> [ 1026.444051569       0x4b24c1670]   dbg_send_ep_cmd: ep0out: cmd
>>>> 'Start Transfer' [406] params 00000000 efffa000 00000000 --> status: No
>>>> Resource
>>>
>>> Why did this fail with No Resource? Was it sent before the control TRB
>>> completion?
>>>
>>>> [ 1027.225705425       0x4b3311678]   dbg_trace_log_ctrl: Clear Endpoint
>>>> Feature(Halt ep5in)
>>>> [ 1027.225820165       0x4b3311f14]   dbg_send_ep_cmd: ep5in: cmd 'Clear
>>>> Stall' [405] params 00000000 00000000 00000000 --> status: Successful
>>>> [ 1027.225931467       0x4b331276c]   dbg_send_ep_cmd: ep0in: cmd 'Start
>>>> Transfer' [406] params 00000000 efffa000 00000000 --> status: Successful
>>>> [ 1027.234311467       0x4b3339bed]   dbg_ep_dequeue: ep7in: req
>>>> ffffff87f99b8f00 length 0/61696 zsI ==> -115
>>>> [ 1027.247409123       0x4b337723f]   dbg_send_ep_cmd: ep7in: cmd 'End
>>>> Transfer' [f0d08] params 00000000 00000000 00000000 --> status: Timed Out
>>>>
>>>
>>> If the Start Transfer for ep0 failed and the Setup packet can't be
>>> DMA'ed out, the End Transfer may not go through.
>>>
>>> Can you leave the log unfiltered and is it possible to send as
>>> attachment? It's missing some important info in this log.
>>>
>> Are there any specific logs you were looking for?
>> trace_dwc3_event
>> trace_dwc3_prepare_trb
>>
>> Part of reproducing this issue will not allow me to enable tracing, so I
>> have to make changes in our driver to reroute the logs elsewhere.  So
>> far I've added changes to do:
>> 	trace_dwc3_ctrl_req
>> 	trace_dwc3_ep_queue
>> 	trace_dwc3_ep_dequeue
>> 	trace_dwc3_gadget_giveback
>> 	trace_dwc3_gadget_ep_cmd
>>
>> I can add the above 2 tracepoints as well, but wondering if you needed
>> anything else.
>>
> 
> If possible, please have these in addition to the above.
> 
> trace_dwc3_event
> trace_dwc3_complete_trb
> 
Enabled the traces you recommended.  I think it captures it pretty clear
where the status phase was still in progress when the dequeue came in,
which led to the end transfer timeout.  Let me know if you need another log.

Thanks
Wesley Cheng

-- 
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
a Linux Foundation Collaborative Project
View attachment "a600000.ssusb.trace.txt" of type "text/plain" (166323 bytes)