Re: RPi4 DWC2 gadget doesn't copy data to a buffer in ep0 SETUP + DATA OUT transaction

[Minas Harutyunyan]

Hi Pavel,

On 4/19/2021 5:22 PM, Pavel Hofman wrote:
> 
> Dne 11. 02. 21 v 12:21 Minas Harutyunyan napsal(a):
>> Hi Ruslan,
>>
>> On 2/1/2021 3:44 AM, Ruslan Bilovol wrote:
>>> Hi Minas and other USB experts,
>>>
>>> I'm currently developing new features for UAC1/UAC2 audio gadgets
>>> like Volume/Mute controls which use Control SETUP + DATA OUT
>>> transactions through ep0.
>>>
>>> While it works fine on BeagleBone black board with MUSB UDC,
>>> on Raspberry Pi 4 with DWC2 UDC there is an issue.
>>>
>>> I found that when DWC2 receives ep0 SETUP + DATA OUT transaction,
>>> it doesn't copy data transferred from the host to EP0 in DATA OUT stage
>>> to the usb_request->buf buffer. This buffer contains unchanged data from
>>> previous transactions.
>>>
>>
>> Could you please send debug log with issue and usb trace.
>>
> 
> Hi Minas,
> 
> I confirm this problem with DWC2 gadget on RPi4. I rebased Julian's
> multiple audio clocks patch
> https://urldefense.com/v3/__https://lore.kernel.org/patchwork/patch/803422/__;!!A4F2R9G_pg!J3zujH0Tzsp0DBsJm6EPTzG0vdr9plGNx7jmoik8JvN4NqODulvND5RXZiLE8d70RkUod4ZZ$  on top of Ruslan's
> implicit feedback patches
> https://urldefense.com/v3/__https://patchwork.kernel.org/project/linux-usb/list/?series=&submitter=121671&state=&q=&archive=&delegate=__;!!A4F2R9G_pg!J3zujH0Tzsp0DBsJm6EPTzG0vdr9plGNx7jmoik8JvN4NqODulvND5RXZiLE8d70Rtv_duVh$
> on branch rpi-5.12.y
> https://urldefense.com/v3/__https://github.com/raspberrypi/linux/tree/rpi-5.12.y__;!!A4F2R9G_pg!J3zujH0Tzsp0DBsJm6EPTzG0vdr9plGNx7jmoik8JvN4NqODulvND5RXZiLE8d70Rkqjb2Qb$  and compiled for arm64.
> 
> When USB host switches audio playback to non-default samplerate (from
> 96000 to 192000 in my case), usb_request->buf contains the previous
> default value of 96000, instead of the new value sent by the host - see
> the captured USB packet below:
> 
> ===============
> Frame 9: 68 bytes on wire (544 bits), 68 bytes captured (544 bits) on
> interface usbmon1, id 0
>      Interface id: 0 (usbmon1)
>          Interface name: usbmon1
>      Encapsulation type: USB packets with Linux header and padding (115)
>      Arrival Time: Apr 19, 2021 13:41:25.146650000 CEST
>      [Time shift for this packet: 0.000000000 seconds]
>      Epoch Time: 1618832485.146650000 seconds
>      [Time delta from previous captured frame: 0.000050000 seconds]
>      [Time delta from previous displayed frame: 0.000050000 seconds]
>      [Time since reference or first frame: 6.013518000 seconds]
>      Frame Number: 9
>      Frame Length: 68 bytes (544 bits)
>      Capture Length: 68 bytes (544 bits)
>      [Frame is marked: False]
>      [Frame is ignored: False]
>      [Protocols in frame: usb]
> USB URB
>      [Source: host]
>      [Destination: 1.14.0]
>      URB id: 0xffff8c37444f2480
>      URB type: URB_SUBMIT ('S')
>      URB transfer type: URB_CONTROL (0x02)
>      Endpoint: 0x00, Direction: OUT
>          0... .... = Direction: OUT (0)
>          .... 0000 = Endpoint number: 0
>      Device: 14
>      URB bus id: 1
>      Device setup request: relevant (0)
>      Data: present (0)
>      URB sec: 1618832485
>      URB usec: 146650
>      URB status: Operation now in progress (-EINPROGRESS) (-115)
>      URB length [bytes]: 4
>      Data length [bytes]: 4
>      [Response in: 10]
>      Interval: 0
>      Start frame: 0
>      Copy of Transfer Flags: 0x00000000
>          .... .... .... .... .... .... .... ...0 = Short not OK: False
>          .... .... .... .... .... .... .... ..0. = ISO ASAP: False
>          .... .... .... .... .... .... .... .0.. = No transfer DMA map: False
>          .... .... .... .... .... .... ..0. .... = No FSBR: False
>          .... .... .... .... .... .... .0.. .... = Zero Packet: False
>          .... .... .... .... .... .... 0... .... = No Interrupt: False
>          .... .... .... .... .... ...0 .... .... = Free Buffer: False
>          .... .... .... .... .... ..0. .... .... = Dir IN: False
>          .... .... .... ...0 .... .... .... .... = DMA Map Single: False
>          .... .... .... ..0. .... .... .... .... = DMA Map Page: False
>          .... .... .... .0.. .... .... .... .... = DMA Map SG: False
>          .... .... .... 0... .... .... .... .... = Map Local: False
>          .... .... ...0 .... .... .... .... .... = Setup Map Single: False
>          .... .... ..0. .... .... .... .... .... = Setup Map Local: False
>          .... .... .0.. .... .... .... .... .... = DMA S-G Combined: False
>          .... .... 0... .... .... .... .... .... = Aligned Temp Buffer: False
>      Number of ISO descriptors: 0
>      [bInterfaceClass: Unknown (0xffff)]
> Setup Data
>      bmRequestType: 0x21
>          0... .... = Direction: Host-to-device
>          .01. .... = Type: Class (0x1)
>          ...0 0001 = Recipient: Interface (0x01)
>      bRequest: 1
>      wValue: 0x0100
>      wIndex: 1792 (0x0700)
>      wLength: 4
>      Data Fragment: 00ee0200      <------------------------------
> ===============
> 
> 

Some clarifications required:
1. gadget works in scatter/gather DMA mode (g_dma_desc is true)?
2. Above captured Host side USB packet corresponds in dmesg to line#39907:

[ 1261.789552] dwc2 fe980000.usb: ctrl Type=21, Req=01, V=0100, I=0700, 
L=0004

Correct?

3. You assume that issue seen in below printk's (lines##39923-39927):

[ 1261.789640] g_audio gadget: Calling uac2_cs_control_sam_freq 1.
[ 1261.789652] g_audio gadget: Calling uac2_cs_control_sam_freq 2.
[ 1261.789655] g_audio gadget: uac2_cs_control_sam_freq val: 96000.
[ 1261.789659] g_audio gadget: Calling uac2_cs_control_sam_freq OUT.
[ 1261.789665] Calling u_audio_set_capture_srate with srate 96000

Instead both 96000 should be 192000? Could you please provide me 
messages sequence for correct behaviour for 192000.

4. Below dmesg fragment not corresponds to observed issue, it's just for 
show added printk's in g_audio. Correct?

Thanks,
Minas


> The value sent 00ee0200 corresponds to 192000, but the gadget received
> the original 96000 (I added some printks to g_audio):
> 
> ==========
> [ 1260.277857] dwc2 fe980000.usb: ep0: req 00000000cf0a7502:
> 4@000000000e574c90, noi=0, zero=0, snok=0
> [ 1260.277865] dwc2 fe980000.usb: dwc2_hsotg_start_req:
> DxEPCTL=0x00028000, ep 0, dir in
> [ 1260.277870] dwc2 fe980000.usb: ureq->length:4 ureq->actual:0
> [ 1260.277886] dwc2 fe980000.usb: ep0 state:1
> [ 1260.277913] dwc2 fe980000.usb: req->length:4 req->actual:4 req->zero:0
> [ 1260.277944] dwc2 fe980000.usb: zlp packet received
> [ 1260.277948] dwc2 fe980000.usb: complete: ep 0000000018e5b31a ep0, req
> 00000000cf0a7502, 0 => 0000000023e79ed8
> [ 1260.277984] dwc2 fe980000.usb: ureq->length:8 ureq->actual:0
> [ 1260.278078] dwc2 fe980000.usb: dwc2_hsotg_epint: ep0(out)
> DxEPINT=0x00000018
> [ 1260.278104] dwc2 fe980000.usb: ep0: req 00000000cf0a7502:
> 4@000000000e574c90, noi=0, zero=0, snok=0
> [ 1260.278128] dwc2 fe980000.usb: dwc2_hsotg_start_req:
> 0x00000000fb0cb800 => 0x00000b14
> [ 1260.278163] dwc2 fe980000.usb: dwc2_hsotg_epint: XferCompl:
> DxEPCTL=0x00028000, DXEPTSIZ=00000000
> [ 1260.278182] g_audio gadget: Calling uac2_cs_control_sam_freq 2.
> [ 1260.278186] g_audio gadget: uac2_cs_control_sam_freq val: 96000.
> ============
> 
> Please find attached the whole dmesg from modprobing the gadget modules
> through playback of 192000.
> 
> Please let me know if you need any more logs/tests. Thank you very much
> for your help.
> 
> Best regards,
> 
> Pavel.
> 
> 
>