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

[Pavel Hofman]

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://lore.kernel.org/patchwork/patch/803422/ on top of Ruslan's
implicit feedback patches
https://patchwork.kernel.org/project/linux-usb/list/?series=&submitter=121671&state=&q=&archive=&delegate=
on branch rpi-5.12.y
https://github.com/raspberrypi/linux/tree/rpi-5.12.y 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      <------------------------------
===============


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.

Attachment: dmesg.log.bz2
Description: application/bzip