vpelletier / python-functionfs

Pythonic API for linux's functionfs
GNU General Public License v3.0
40 stars 13 forks source link

Sample HID Mouse - Windows host works great - Linux host fails enumeration #22

Closed KiwiLostInMelb closed 2 years ago

KiwiLostInMelb commented 2 years ago

Hi,

I have a really weird issue and wonder if it is related to chunking when sending the report descriptor to the host side.

Device and background: Jetson Nano with latest jetpack, disabled jetson default configfs service, disabled udev rules for the same - I.e. configfs all ready to work.

Scenario: Your HID Mouse test app works fine when I have a windows host connected although there is an initial connect, disconnect and connect.

But when I connect the same to a linux host I get enumeration issues which is really weird. It almost seems as if there is something chunking the writes for linux whereas windows tries something first, fails and then requests smaller chunks one at a time?

Configfs (on the jetson nano) has a fixed bMaxPacketSize0 of 64 (seems not able to be changed - I have tried setting this but it is ignored) and it might be that your library is limiting report descriptor ep0 transfers to a lower buffer size - possibly based on endpoint bLength (which is 7 for this one) instead of bMaxPacketSize0?

It seems like windows handles this - hence the connect (at highest rate?), disconnect and then reconnect (at a fixed lower buffer size set in windows?) but linux hosts dont do this - they just fail the first enumeration. I realise that this is probably Jetson Nano specific but does this sound like it could be the issue?

I'm not really a python programmer. I'm using python for ease of integration into a webcam detection routine. Hence I'm looking for a bit of help here.

Im pulling my hair out on this one :)

Here is the output from the linux host side when checking enumeration:

sudo lsusb -d1d6b:0104 -v

Bus 001 Device 010: ID 1d6b:0104 Linux Foundation Multifunction Composite Gadget Device Descriptor: bLength 18 bDescriptorType 1 bcdUSB 2.10 bDeviceClass 0 (Defined at Interface level) bDeviceSubClass 0 bDeviceProtocol 0 bMaxPacketSize0 64 idVendor 0x1d6b Linux Foundation idProduct 0x0104 Multifunction Composite Gadget bcdDevice 4.09 iManufacturer 1 (error) iProduct 2 (error) iSerial 3 (error) bNumConfigurations 1 Configuration Descriptor: bLength 9 bDescriptorType 2 wTotalLength 34 bNumInterfaces 1 bConfigurationValue 1 iConfiguration 4 (error) bmAttributes 0x80 (Bus Powered) MaxPower 500mA Interface Descriptor: bLength 9 bDescriptorType 4 bInterfaceNumber 0 bAlternateSetting 0 bNumEndpoints 1 bInterfaceClass 3 Human Interface Device bInterfaceSubClass 0 No Subclass bInterfaceProtocol 0 None iInterface 0 HID Device Descriptor: bLength 9 bDescriptorType 33 bcdHID 1.11 bCountryCode 0 Not supported bNumDescriptors 1 bDescriptorType 34 Report wDescriptorLength 50 Warning: incomplete report descriptor Report Descriptor: (length is 7) Item(Main ): (null), data=none Item(Main ): (null), data=none Item(Main ): (null), data=none Item(Main ): (null), data=none Item(Main ): (null), data=none Item(Main ): (null), data=none Item(Main ): (null), data=none Endpoint Descriptor: bLength 7 bDescriptorType 5 bEndpointAddress 0x81 EP 1 IN bmAttributes 3 Transfer Type Interrupt Synch Type None Usage Type Data wMaxPacketSize 0x0003 1x 3 bytes bInterval 10 Device Status: 0x0401 Self Powered

vpelletier commented 2 years ago

Configfs (on the jetson nano) has a fixed bMaxPacketSize0 of 64 (seems not able to be changed - I have tried setting this but it is ignored)

I checked the USB 2 and 3 specs, and this seems to be what the standard requires for high-speed devices, with low- and full-speed devices limited to powers of two from 8 to 64, and super-speed devices limited to 512 (encoded as 0x09).

linux hosts dont do this - they just fail the first enumeration. I realise that this is probably Jetson Nano specific but does this sound like it could be the issue?

This could be UDC-specific (which, if I'm reading the devicetrees right, seem to be tegra-xudc), as enumeration should be in the hands of the UDC - which also means this issue will likely have to be brought to this code's maintainers.

Here is the output from the linux host side when checking enumeration:

Mmh, but if this is present on the host, then it must mean the USB enumeration worked.

For reference, I pasted below what I get on a Linux host with the dummy_hcd UDC.

The differences I spot at a glance are:

$ sudo lsusb -vd 1d6b:0104

Bus 005 Device 015: ID 1d6b:0104 Linux Foundation Multifunction Composite Gadget
Device Descriptor:
  bLength                18
  bDescriptorType         1
  bcdUSB               2.00
  bDeviceClass            0
  bDeviceSubClass         0
  bDeviceProtocol         0
  bMaxPacketSize0        64
  idVendor           0x1d6b Linux Foundation
  idProduct          0x0104 Multifunction Composite Gadget
  bcdDevice            5.10
  iManufacturer           1 python-functionfs
  iProduct                2 HID mouse demo
  iSerial                 3
  bNumConfigurations      1
  Configuration Descriptor:
    bLength                 9
    bDescriptorType         2
    wTotalLength       0x0022
    bNumInterfaces          1
    bConfigurationValue     1
    iConfiguration          4 mouse demo function
    bmAttributes         0x80
      (Bus Powered)
    MaxPower              500mA
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        0
      bAlternateSetting       0
      bNumEndpoints           1
      bInterfaceClass         3 Human Interface Device
      bInterfaceSubClass      0
      bInterfaceProtocol      0
      iInterface              0
        HID Device Descriptor:
          bLength                 9
          bDescriptorType        33
          bcdHID               1.11
          bCountryCode            0 Not supported
          bNumDescriptors         1
          bDescriptorType        34 Report
          wDescriptorLength      50
         Report Descriptors:
           ** UNAVAILABLE **
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x81  EP 1 IN
        bmAttributes            3
          Transfer Type            Interrupt
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0003  1x 3 bytes
        bInterval              10
Device Qualifier (for other device speed):
  bLength                10
  bDescriptorType         6
  bcdUSB               2.00
  bDeviceClass            0
  bDeviceSubClass         0
  bDeviceProtocol         0
  bMaxPacketSize0        64
  bNumConfigurations      1
Device Status:     0x0000
  (Bus Powered)
KiwiLostInMelb commented 2 years ago

Thank you for looking into this - so I completely removed functionfs and reinstalled and tried on a different linux host it is now enumerating - might have been an old version?

I thought I had already done this but it might have been a separate sdcard for the device. So sorry for the mixup. I am normally more careful than this.

And it now enumerates!!!

But I still get an availability error (below). Any ideas what could cause this? Is it a host or device side error? This will help me track it down better.

Bus 003 Device 003: ID 1d6b:0104 Linux Foundation Multifunction Composite Gadget Device Descriptor: bLength 18 bDescriptorType 1 bcdUSB 2.10 bDeviceClass 0 bDeviceSubClass 0 bDeviceProtocol 0 bMaxPacketSize0 64 idVendor 0x1d6b Linux Foundation idProduct 0x0104 Multifunction Composite Gadget bcdDevice 4.09 iManufacturer 1 python-functionfs iProduct 2 HID mouse demo iSerial 3 0123456789ABCDEF bNumConfigurations 1 Configuration Descriptor: bLength 9 bDescriptorType 2 wTotalLength 0x0022 bNumInterfaces 1 bConfigurationValue 1 iConfiguration 4 (error) bmAttributes 0x80 (Bus Powered) MaxPower 500mA Interface Descriptor: bLength 9 bDescriptorType 4 bInterfaceNumber 0 bAlternateSetting 0 bNumEndpoints 1 bInterfaceClass 3 Human Interface Device bInterfaceSubClass 0 bInterfaceProtocol 0 iInterface 0 HID Device Descriptor: bLength 9 bDescriptorType 33 bcdHID 1.11 bCountryCode 0 Not supported bNumDescriptors 1 bDescriptorType 34 Report wDescriptorLength 50 Report Descriptor: (length is -7) Endpoint Descriptor: bLength 7 bDescriptorType 5 bEndpointAddress 0x81 EP 1 IN bmAttributes 3 Transfer Type Interrupt Synch Type None Usage Type Data wMaxPacketSize 0x0003 1x 3 bytes bInterval 10 cannot read device status, Resource temporarily unavailable (11)

As you say, it might be a kernel issue but windows works perfectly so its a bit confusing. I am unable to update the kernel as this is already the latest for the NVidia Jetson and this is what they support.

DMesg looks good on the host: [1205922.926522] usb 3-3: USB disconnect, device number 8 [1205927.914388] usb 3-3: new high-speed USB device number 9 using xhci_hcd [1205928.042922] usb 3-3: New USB device found, idVendor=1d6b, idProduct=0104, bcdDevice= 4.09 [1205928.042938] usb 3-3: New USB device strings: Mfr=1, Product=2, SerialNumber=3 [1205928.042944] usb 3-3: Product: HID mouse demo [1205928.042948] usb 3-3: Manufacturer: python-functionfs [1205928.042952] usb 3-3: SerialNumber: 0123456789ABCDEF

And on the device:

[ 1729.546192] configfs-gadget gadget: high-speed config #1: c [ 1729.546316] tegra-xudc-new 700d0000.xudc: ep 3 (type: 3, dir: in) enabled [ 1729.546828] android_work: sent uevent USB_STATE=CONNECTED [ 1729.546959] android_work: sent uevent USB_STATE=CONFIGURED

Grr code tags not working for me so I edited it back.

vpelletier commented 2 years ago

iConfiguration 4 (error)

[...]

Report Descriptor: (length is -7)

There are still some fishy things going on in the descriptors, though. This could be the kernel somehow accessing uninitialised memory, and this time the stars happened to align a bit better than on your previous copy/paste. Or could the functionfs module be misinterpreting the values I'm pushing to it (which then would be a bug on my side) ? It would seem unlikely as I assume the Jetson is 32 or 64bits little-endian, and I know first-hand that this is working on armel (raspberry pi zero with dwc2) and x86_64 (both intel edison with dwc3 and "regular" desktop with dummy_hcd).

Any ideas what could cause this? Is it a host or device side error? This will help me track it down better.

I tend to suspect the device side, as USB host-side on Linux is more mature (...if maybe not as lenient towards misbehaving devices as Windows) than device-side. If you can get a usbmon/wireshark capture from a Linux host this should help narrow it down.

As you say, it might be a kernel issue but windows works perfectly so its a bit confusing.

Could you check the descriptors on windows ? I think they may be available in the device manager, although maybe one field at a time. Maybe windows is more resilient to the occasional device unexpected behaviour ? Maybe you will see similar corruptions.

Grr code tags not working for me so I edited it back.

The quoting mark around here is three backquotes (```) on a line of their own, before and after each block.

KiwiLostInMelb commented 2 years ago

USBMon output - for a connect - on the HOST

sudo cat /sys/kernel/debug/usb/usbmon/2u
ffff89f472f4d000 2587921064 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
ffff89f472f4d000 2587921147 C Ci:2:001:0 0 4 = 07050000
ffff89f472f4d000 2587921154 S Ci:2:001:0 s a3 00 0000 0002 0004 4 <
ffff89f472f4d000 2587921158 C Ci:2:001:0 0 4 = 00010000
ffff89f44262cf00 2587921161 S Ii:2:001:1 -115:2048 4 <
ffff89f44262cf00 2587921270 C Ii:2:001:1 0:2048 1 = 00
ffff89f44262cf00 2587921274 S Ii:2:001:1 -115:2048 4 <
ffff89f44262cf00 2587947276 C Ii:2:001:1 0:2048 1 = 00
ffff89f44262cf00 2587947291 S Ii:2:001:1 -115:2048 4 <
ffff89f44262cf00 2587973300 C Ii:2:001:1 0:2048 1 = 02
ffff89f44262cf00 2587973315 S Ii:2:001:1 -115:2048 4 <
ffff89f472f4d000 2587973381 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
ffff89f472f4d000 2587973462 C Ci:2:001:0 0 4 = 03050400
ffff89f472f4d000 2587973486 S Co:2:001:0 s 23 01 0012 0001 0000 0
ffff89f472f4d000 2587973493 C Co:2:001:0 0 0
ffff89f472f4d000 2587985299 S Ci:2:001:0 s a3 00 0000 0001 0004 4 <
ffff89f472f4d000 2587985318 C Ci:2:001:0 0 4 = 03050000
ffff89f472f4d000 2587997309 S Ci:2:002:0 s 80 00 0000 0000 0002 2 <
ffff89f472f4d000 2587997486 C Ci:2:002:0 0 2 = 0300
ffff89f472f4d000 2587997502 S Co:2:002:0 s 00 01 0001 0000 0000 0
ffff89f472f4d000 2587997594 C Co:2:002:0 0 0
ffff89f472f4d000 2587997607 S Ci:2:002:0 s a3 00 0000 0001 0004 4 <
ffff89f472f4d000 2587997733 C Ci:2:002:0 0 4 = 00010000
ffff89f472f4d000 2587997751 S Ci:2:002:0 s a3 00 0000 0002 0004 4 <
ffff89f472f4d000 2587997836 C Ci:2:002:0 0 4 = 00010000
ffff89f472f4d000 2587997842 S Ci:2:002:0 s a3 00 0000 0003 0004 4 <
ffff89f472f4d000 2587997960 C Ci:2:002:0 0 4 = 00010000
ffff89f472f4d000 2587997964 S Ci:2:002:0 s a3 00 0000 0004 0004 4 <
ffff89f472f4d000 2587998085 C Ci:2:002:0 0 4 = 00010000
ffff89f472f4d000 2587998089 S Ci:2:002:0 s a3 00 0000 0005 0004 4 <
ffff89f472f4d000 2587998210 C Ci:2:002:0 0 4 = 00010000
ffff89f472f4d000 2587998215 S Ci:2:002:0 s a3 00 0000 0006 0004 4 <
ffff89f472f4d000 2587998335 C Ci:2:002:0 0 4 = 01010100
ffff89f472f4d000 2587998341 S Co:2:002:0 s 23 01 0010 0006 0000 0
ffff89f472f4d000 2587998459 C Co:2:002:0 0 0
ffff89f472f4d000 2587998464 S Ci:2:002:0 s a3 00 0000 0007 0004 4 <
ffff89f472f4d000 2587998585 C Ci:2:002:0 0 4 = 00010000
ffff89f472f4d000 2587998592 S Ci:2:002:0 s a3 00 0000 0008 0004 4 <
ffff89f472f4d000 2587998709 C Ci:2:002:0 0 4 = 00010000
ffff89f449c4d540 2588102307 S Ii:2:002:1 -115:2048 2 <
ffff89f472f4d000 2588102334 S Ci:2:002:0 s a3 00 0000 0006 0004 4 <
ffff89f472f4d000 2588102486 C Ci:2:002:0 0 4 = 01010000
ffff89f472f4d000 2588102511 S Co:2:002:0 s 23 03 0004 0006 0000 0
ffff89f472f4d000 2588102608 C Co:2:002:0 0 0
ffff89f472f4d000 2588114299 S Ci:2:002:0 s a3 00 0000 0006 0004 4 <
ffff89f472f4d000 2588114356 C Ci:2:002:0 0 4 = 03051000
ffff89f472f4d000 2588114373 S Co:2:002:0 s 23 01 0014 0006 0000 0
ffff89f472f4d000 2588114484 C Co:2:002:0 0 0
ffff89f472f4d000 2588166331 S Ci:2:000:0 s 80 06 0100 0000 0040 64 <
ffff89f472f4d000 2588166886 C Ci:2:000:0 0 18 = 12011002 00000040 6b1d0401 09040102 0301
ffff89f472f4d000 2588166903 S Co:2:002:0 s 23 03 0004 0006 0000 0
ffff89f472f4d000 2588166970 C Co:2:002:0 0 0
ffff89f472f4d000 2588178299 S Ci:2:002:0 s a3 00 0000 0006 0004 4 <
ffff89f472f4d000 2588178350 C Ci:2:002:0 0 4 = 03051000
ffff89f472f4d000 2588178359 S Co:2:002:0 s 23 01 0014 0006 0000 0
ffff89f472f4d000 2588178469 C Co:2:002:0 0 0
ffff89f472f4d000 2588230306 S Co:2:000:0 s 00 05 000a 0000 0000 0
ffff89f472f4d000 2588230483 C Co:2:000:0 0 0
ffff89f472f4db40 2588244280 S Ci:2:010:0 s 80 06 0100 0000 0012 18 <
ffff89f472f4db40 2588244466 C Ci:2:010:0 0 18 = 12011002 00000040 6b1d0401 09040102 0301
ffff89f472f4db40 2588244512 S Ci:2:010:0 s 80 06 0f00 0000 0005 5 <
ffff89f472f4db40 2588244709 C Ci:2:010:0 0 5 = 050f1600 02
ffff89f472f4db40 2588244730 S Ci:2:010:0 s 80 06 0f00 0000 0016 22 <
ffff89f472f4db40 2588244834 C Ci:2:010:0 0 22 = 050f1600 02071002 06000000 0a100300 0f000101 f401
ffff89f472f4db40 2588244859 S Ci:2:010:0 s 80 06 0200 0000 0009 9 <
ffff89f472f4db40 2588245083 C Ci:2:010:0 0 9 = 09022200 01010480 fa
ffff89f472f4db40 2588245103 S Ci:2:010:0 s 80 06 0200 0000 0022 34 <
ffff89f472f4db40 2588245333 C Ci:2:010:0 0 34 = 09022200 01010480 fa090400 00010300 00000921 11010001 22320007 05810303
ffff89f472f4db40 2588245358 S Ci:2:010:0 s 80 06 0300 0000 00ff 255 <
ffff89f472f4db40 2588245583 C Ci:2:010:0 0 4 = 04030904
ffff89f472f4db40 2588245604 S Ci:2:010:0 s 80 06 0302 0409 00ff 255 <
ffff89f472f4db40 2588245708 C Ci:2:010:0 0 30 = 1e034800 49004400 20006d00 6f007500 73006500 20006400 65006d00 6f00
ffff89f472f4db40 2588245729 S Ci:2:010:0 s 80 06 0301 0409 00ff 255 <
ffff89f472f4db40 2588245833 C Ci:2:010:0 0 36 = 24037000 79007400 68006f00 6e002d00 66007500 6e006300 74006900 6f006e00
ffff89f472f4db40 2588245852 S Ci:2:010:0 s 80 06 0303 0409 00ff 255 <
ffff89f472f4db40 2588245958 C Ci:2:010:0 0 34 = 22033000 31003200 33003400 35003600 37003800 39004100 42004300 44004500
ffff89f472f4db40 2588246188 S Co:2:010:0 s 00 09 0001 0000 0000 0
ffff89f472f4db40 2588246334 C Co:2:010:0 0 0
ffff89f472f4db40 2588246416 S Ci:2:010:0 s 80 06 0304 0409 00ff 255 <
ffff89f472f4db40 2588246585 C Ci:2:010:0 0 40 = 28036d00 6f007500 73006500 20006400 65006d00 6f002000 66007500 6e006300
ffff89f472f4db40 2588246668 S Ci:2:010:0 s 80 06 0303 0409 00ff 255 <
ffff89f472f4db40 2588246835 C Ci:2:010:0 0 34 = 22033000 31003200 33003400 35003600 37003800 39004100 42004300 44004500
ffff89f472f4db40 2588246878 S Co:2:010:0 s 21 0a 0000 0000 0000 0
ffff89f472f4db40 2588249233 C Co:2:010:0 -32 0
ffff89f472f4db40 2588249295 S Ci:2:010:0 s 81 06 2200 0000 0032 50 <
ffff89f472f4db40 2593385581 C Ci:2:010:0 -2 0
ffff89f472f4db40 2593385645 S Ci:2:010:0 s 81 06 2200 0000 0032 50 <

Last 2 lines repeat

BTW Jetson Nano is ARM64 so probably identical cpu hardware to pi4 - with an nvidia card built in and uses shared 4GB memory. Built for computer vision.

A disconnect if its helpful. I suspect not.

sudo cat /sys/kernel/debug/usb/usbmon/2u
ffff89f4c241b480 3222121358 C Ci:2:011:0 -2 0
ffff89f4c241b480 3222121382 S Ci:2:011:0 s 81 06 2200 0000 0032 50 <
ffff89f4c241b480 3222186078 C Ci:2:011:0 -71 0
ffff89f4c241b480 3222186091 S Ci:2:011:0 s 81 06 2200 0000 0032 50 <
ffff89f4c241b480 3222190327 C Ci:2:011:0 -71 0
ffff89f449c4d540 3222241143 C Ii:2:002:1 0:2048 2 = 4000
ffff89f449c4d540 3222241158 S Ii:2:002:1 -115:2048 2 <
ffff89f4c241bb40 3222241175 S Ci:2:002:0 s a3 00 0000 0006 0004 4 <
ffff89f4c241bb40 3222241348 C Ci:2:002:0 0 4 = 00010100
ffff89f4c241bb40 3222241370 S Co:2:002:0 s 23 01 0010 0006 0000 0
ffff89f4c241bb40 3222241475 C Co:2:002:0 0 0
ffff89f4c241bc00 3222241715 S Ci:2:002:0 s a3 00 0000 0006 0004 4 <
ffff89f4c241bc00 3222241850 C Ci:2:002:0 0 4 = 00010000
ffff89f4c241bc00 3222268283 S Ci:2:002:0 s a3 00 0000 0006 0004 4 <
ffff89f4c241bc00 3222268473 C Ci:2:002:0 0 4 = 00010000
ffff89f4c241bc00 3222295279 S Ci:2:002:0 s a3 00 0000 0006 0004 4 <
ffff89f4c241bc00 3222295328 C Ci:2:002:0 0 4 = 00010000
ffff89f4c241bc00 3222322298 S Ci:2:002:0 s a3 00 0000 0006 0004 4 <
ffff89f4c241bc00 3222322475 C Ci:2:002:0 0 4 = 00010000
ffff89f4c241bc00 3222349292 S Ci:2:002:0 s a3 00 0000 0006 0004 4 <
ffff89f4c241bc00 3222349472 C Ci:2:002:0 0 4 = 00010000
ffff89f449c4d540 3222351654 C Ii:2:002:1 -2:2048 0
ffff89f4c241bc00 3222351673 S Co:2:002:0 s 00 03 0001 0000 0000 0
ffff89f4c241bc00 3222351846 C Co:2:002:0 0 0
ffff89f4c241bc00 3222351864 S Co:2:001:0 s 23 03 0002 0001 0000 0
ffff89f4c241bc00 3222351878 C Co:2:001:0 0 0
ffff89f44262cf00 3222363308 C Ii:2:001:1 -2:2048 0
KiwiLostInMelb commented 2 years ago

Windows provides sweetfa information grrrr

Instance ID:                HID\VID_1D6B&PID_0104\7&2d6bdfda&0&0000
Device Description:         HID-compliant mouse
Class Name:                 Mouse
Class GUID:                 {4d36e96f-e325-11ce-bfc1-08002be10318}
Manufacturer Name:          Microsoft
Status:                     Started
Driver Name:                msmouse.inf
Hardware IDs:               HID\VID_1D6B&PID_0104&REV_0409
                            HID\VID_1D6B&PID_0104
                            HID\VID_1D6B&UP:0001_U:0002
                            HID_DEVICE_SYSTEM_MOUSE
                            HID_DEVICE_UP:0001_U:0002
                            HID_DEVICE
Matching Drivers:
    Driver Name:            msmouse.inf
    Provider Name:          Microsoft
    Class Name              Mouse
    Class GUID:             {4d36e96f-e325-11ce-bfc1-08002be10318}
    Driver Version:         06/21/2006 10.0.19041.1
    Matching Device ID:     HID_DEVICE_SYSTEM_MOUSE
    Driver Rank:            00FF1003
    Driver Status:          Best Ranked / Installed

    Driver Name:            input.inf
    Provider Name:          Microsoft
    Class Name              HIDClass
    Class GUID:             {745a17a0-74d3-11d0-b6fe-00a0c90f57da}
    Driver Version:         06/21/2006 10.0.19041.868
    Matching Device ID:     HID_DEVICE
    Driver Rank:            00FF1005
    Driver Status:          Outranked
Parent:                     USB\VID_1D6B&PID_0104\0123456789ABCDEF
vpelletier commented 2 years ago

I see a problem in the usbmon output: the request for the HID event descriptor gets an error response:

ffff89f472f4db40 2588249295 S Ci:2:010:0 s 81 06 2200 0000 0032 50 <
ffff89f472f4db40 2593385581 C Ci:2:010:0 -2 0

-2 being ENOENT. I must recheck how I setup this descriptor, as I see my code is sending this descriptor on-demand from interface-specific control requests... Maybe the gadget kernel only expects them sent as part of the USB-standard descriptors ?

vpelletier commented 2 years ago

I checked some more and I do not see what I would be doing wrong: I cannot just append a HID report descriptor to the USB interface descriptor, the kernel will reject that. Also I see that in 4.9 there was already ffs_func_req_match in drivers/usb/gadget/function/f_fs.c, which is what directs standard descriptor requests to the userland daemon when that request targets its interface (or an endpoint, for that matter).

So I do not see why the gadget would reject this request: it should pass it on to the gadget process, which should have an AIO request block submitted and polling a corresponding eventfd to be notified whenever the endpoint 0 pseudo-file it trying to get its attention - and then handle it in the codepath selected by these conditions.

Maybe you could add a debug print in this method ? First you have to locate exactly which file is being used. In a python virtualenv, it should be something like: $VIRTUALENV_ROOT/lib/python*/site-packages/functionfs/__init__.py. Then, on the line after def onSetup(...): you can add print('onSetup', hex(request_type), hex(request), hex(value), hex(index), hex(length)). This should appear on the terminal running my example soon after it is plugged in. If not, this explains the error, and means you will have to identify where python is stuck at:

vpelletier commented 2 years ago

Another approach to debugging could be to run strace on the process... This will produce a large output, so it would be very helpful if you can narrow it down: all the early stat/open/read of python sources is unlikely to be helpful, but stuff after the first open("/sys/kernel/config/.../ep0", ...) (or so) will be a lot more relevant.

KiwiLostInMelb commented 2 years ago

Process events forever is called for the test.

I am wondering - looking at the code - and I'm not great with python - it looks like you are sending the setup in 2 separate writes. Could the kernel be detecting this?

I am looking at init.py around line 1040.

Is it worth a try concatenating and sending in one write cycle? As Im not python literate I dont know the libraries. I would guess converting the function desc and strings to a byte array, concatenate first and then put in a readable buffer might work better?

Guessing a bit based on what I can see ocurring....

vpelletier commented 2 years ago

it looks like you are sending the setup in 2 separate writes.

You are correct. This is actually expected by the kernel: the write handler for endpoint zero has 3 personalities:

So I agree this looks a bit weird, but this is how the kernel expects it in order to properly switch from FFS_READ_DESCRIPTORS to FFS_READ_STRINGS between writes.

KiwiLostInMelb commented 2 years ago

Ok, so I think I have found the problem...... And it is not your code but thank you so much for pointing me in the right direction.

I found this when I went back to the raw documentation and tried to create a gadget totally manually using the console.

It failed creating the functions/hid.usb0 directory. Hmmm why? Ok, so its a fs overlay but needs to be supported/allowed/enabled. It created rndis.usb0 when I tested so whats the issue with hid being a problem?

I downloaded the kernel source and went through the configuration carefully. Configfs is on as expected BUT CONFIG_USB_CONFIGFS_F_HID was not set - this means that HID was not a valid fs overlay (hid.usb0 folder).

So (grrr not nice words in case they are watching) nvidia caused all these issues - I'll update them on their forum so that they set it for the next release.

I am not a kernel guy but can at least read a make config file :)

I am in the process of recompiling the kernel and modules and will let you know the result.

Thank you soo much for your help.

Still doesnt explain to me why windows works though - is there some compatibility mode when working with HID that windows accepts but not linux?

More info to come....

KiwiLostInMelb commented 2 years ago

Ok, so I am lot further...... but still have a bug somehwere.

If I create the gadget manually using the following:

#!/bin/bash

cd /sys/kernel/config/usb_gadget/
mkdir -p mymouse
cd mymouse
echo 0x1d6b > idVendor # Linux Foundation
echo 0x0104 > idProduct # Multifunction Composite Gadget
echo 0x0100 > bcdDevice # v1.0.0
echo 0x0200 > bcdUSB # USB2
mkdir -p strings/0x409
echo "fedcba9876543210" > strings/0x409/serialnumber
echo "test usb" > strings/0x409/manufacturer
echo "test USB Device" > strings/0x409/product
mkdir -p configs/c.1/strings/0x409
echo "Config 1: my config" > configs/c.1/strings/0x409/configuration
echo 100 > configs/c.1/MaxPower

mkdir -p functions/hid.usb0
echo 1 > functions/hid.usb0/protocol
echo 1 > functions/hid.usb0/subclass
echo 8 > functions/hid.usb0/report_length
echo -ne \\x05\\x01\\x09\\x02\\xa1\\x01\\x09\\x01\\xa1\\x00\\x05\\x09\\x19\\x01\\x29\\x03\\x15\\x00\\x25\\x01\\x95\\x03\\x75\\x01\\x81\\x02\\x95\\x01\\x75\\x05\\x81\\x01\\x05\\x01\\x09\\x30\\x09\\x31\\x15\\x81\\x25\\x7f\\x75\\x08\\x95\\x02\\x81\\x06\\xc0\\xc0 > functions/hid.usb0/report_desc

ln -s functions/hid.usb0 configs/c.1/

ls /sys/class/udc > UDC

I get this output:

Bus 002 Device 025: ID 1d6b:0104 Linux Foundation Multifunction Composite Gadget
Device Descriptor:
  bLength                18
  bDescriptorType         1
  bcdUSB               2.10
  bDeviceClass            0
  bDeviceSubClass         0
  bDeviceProtocol         0
  bMaxPacketSize0        64
  idVendor           0x1d6b Linux Foundation
  idProduct          0x0104 Multifunction Composite Gadget
  bcdDevice            1.00
  iManufacturer           1 test usb
  iProduct                2 test USB Device
  iSerial                 3 fedcba9876543210
  bNumConfigurations      1
  Configuration Descriptor:
    bLength                 9
    bDescriptorType         2
    wTotalLength       0x0029
    bNumInterfaces          1
    bConfigurationValue     1
    iConfiguration          4 Config 1: my config
    bmAttributes         0x80
      (Bus Powered)
    MaxPower              100mA
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        0
      bAlternateSetting       0
      bNumEndpoints           2
      bInterfaceClass         3 Human Interface Device
      bInterfaceSubClass      1 Boot Interface Subclass
      bInterfaceProtocol      1 Keyboard
      iInterface              5 HID Interface
        HID Device Descriptor:
          bLength                 9
          bDescriptorType        33
          bcdHID               1.01
          bCountryCode            0 Not supported
          bNumDescriptors         1
          bDescriptorType        34 Report
          wDescriptorLength      50
         Report Descriptors:
           ** UNAVAILABLE **
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x81  EP 1 IN
        bmAttributes            3
          Transfer Type            Interrupt
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0008  1x 8 bytes
        bInterval               4
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x01  EP 1 OUT
        bmAttributes            3
          Transfer Type            Interrupt
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0008  1x 8 bytes
        bInterval               4
Binary Object Store Descriptor:
  bLength                 5
  bDescriptorType        15
  wTotalLength       0x0016
  bNumDeviceCaps          2
  USB 2.0 Extension Device Capability:
    bLength                 7
    bDescriptorType        16
    bDevCapabilityType      2
    bmAttributes   0x00000006
      BESL Link Power Management (LPM) Supported
  SuperSpeed USB Device Capability:
    bLength                10
    bDescriptorType        16
    bDevCapabilityType      3
    bmAttributes         0x00
    wSpeedsSupported   0x000f
      Device can operate at Low Speed (1Mbps)
      Device can operate at Full Speed (12Mbps)
      Device can operate at High Speed (480Mbps)
      Device can operate at SuperSpeed (5Gbps)
    bFunctionalitySupport   1
      Lowest fully-functional device speed is Full Speed (12Mbps)
    bU1DevExitLat           1 micro seconds
    bU2DevExitLat         500 micro seconds
Device Status:     0x0001
  Self Powered

When using python-functionfs I get

sudo lsusb -vd 1d6b:0104

Bus 002 Device 026: ID 1d6b:0104 Linux Foundation Multifunction Composite Gadget
Device Descriptor:
  bLength                18
  bDescriptorType         1
  bcdUSB               2.10
  bDeviceClass            0
  bDeviceSubClass         0
  bDeviceProtocol         0
  bMaxPacketSize0        64
  idVendor           0x1d6b Linux Foundation
  idProduct          0x0104 Multifunction Composite Gadget
  bcdDevice            4.09
  iManufacturer           1 python-functionfs
  iProduct                2 HID mouse demo
  iSerial                 3 0123456789ABCDEF
  bNumConfigurations      1
  Configuration Descriptor:
    bLength                 9
    bDescriptorType         2
    wTotalLength       0x0022
    bNumInterfaces          1
    bConfigurationValue     1
    iConfiguration          4 (error)
    bmAttributes         0x80
      (Bus Powered)
    MaxPower              500mA
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        0
      bAlternateSetting       0
      bNumEndpoints           1
      bInterfaceClass         3 Human Interface Device
      bInterfaceSubClass      0
      bInterfaceProtocol      0
      iInterface              0
        HID Device Descriptor:
          bLength                 9
          bDescriptorType        33
          bcdHID               1.11
          bCountryCode            0 Not supported
          bNumDescriptors         1
          bDescriptorType        34 Report
          wDescriptorLength      50
          Report Descriptor: (length is -7)
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x81  EP 1 IN
        bmAttributes            3
          Transfer Type            Interrupt
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0003  1x 3 bytes
        bInterval              10
cannot read device status, Resource temporarily unavailable (11)

So still a problem somewhere but at least I am a LOT further and I know the kernel is ok. I know I cant use the above gadget as it is a sub class and I need a main class that is mouse. Also - it is a keyboard atm but I wanted to see if it would setup correctly and enumerate which is does.

KiwiLostInMelb commented 2 years ago

Trimmed strace output - I added a fixed folder name 'testusb' strace -v -f used

8676  mkdirat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb", 0777) = 0
8676  mkdirat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/strings/0x409", 0777) = 0
8676  openat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/strings/0x409/product", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 5
8676  fstat(5, {st_dev=makedev(0, 16), st_ino=41219, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1633239954 /* 2021-10-03T16:45:54.055362371+1100 */, st_atime_nsec=55362371, st_mtime=1633239954 /* 2021-10-03T16:45:54.055362371+1100 */, st_mtime_nsec=55362371, st_ctime=1633239954 /* 2021-10-03T16:45:54.055362371+1100 */, st_ctime_nsec=55362371}) = 0
8676  ioctl(5, TCGETS, 0x7fe2fba8e0)    = -1 ENOTTY (Inappropriate ioctl for device)
8676  lseek(5, 0, SEEK_CUR)             = 0
8676  write(5, "HID mouse demo", 14)    = 14
8676  close(5)                          = 0
8676  openat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/strings/0x409/manufacturer", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 5
8676  fstat(5, {st_dev=makedev(0, 16), st_ino=41220, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1633239954 /* 2021-10-03T16:45:54.055362371+1100 */, st_atime_nsec=55362371, st_mtime=1633239954 /* 2021-10-03T16:45:54.055362371+1100 */, st_mtime_nsec=55362371, st_ctime=1633239954 /* 2021-10-03T16:45:54.055362371+1100 */, st_ctime_nsec=55362371}) = 0
8676  ioctl(5, TCGETS, 0x7fe2fba8e0)    = -1 ENOTTY (Inappropriate ioctl for device)
8676  lseek(5, 0, SEEK_CUR)             = 0
8676  write(5, "python-functionfs", 17) = 17
8676  close(5)                          = 0
8676  openat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/idVendor", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 5
8676  fstat(5, {st_dev=makedev(0, 16), st_ino=41221, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1633239954 /* 2021-10-03T16:45:54.055362371+1100 */, st_atime_nsec=55362371, st_mtime=1633239954 /* 2021-10-03T16:45:54.055362371+1100 */, st_mtime_nsec=55362371, st_ctime=1633239954 /* 2021-10-03T16:45:54.055362371+1100 */, st_ctime_nsec=55362371}) = 0
8676  ioctl(5, TCGETS, 0x7fe2fbaab0)    = -1 ENOTTY (Inappropriate ioctl for device)
8676  lseek(5, 0, SEEK_CUR)             = 0
8676  write(5, "0x1d6b", 6)             = 6
8676  close(5)                          = 0
8676  openat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/idProduct", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 5
8676  fstat(5, {st_dev=makedev(0, 16), st_ino=41222, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1633239954 /* 2021-10-03T16:45:54.059362409+1100 */, st_atime_nsec=59362409, st_mtime=1633239954 /* 2021-10-03T16:45:54.059362409+1100 */, st_mtime_nsec=59362409, st_ctime=1633239954 /* 2021-10-03T16:45:54.059362409+1100 */, st_ctime_nsec=59362409}) = 0
8676  ioctl(5, TCGETS, 0x7fe2fbaab0)    = -1 ENOTTY (Inappropriate ioctl for device)
8676  lseek(5, 0, SEEK_CUR)             = 0
8676  write(5, "0x104", 5)              = 5
8676  close(5)                          = 0
8676  mkdirat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/configs/c.1", 0777) = 0
8676  mkdirat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/configs/c.1/strings/0x409", 0777) = 0
8676  openat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/configs/c.1/strings/0x409/configuration", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 5
8676  fstat(5, {st_dev=makedev(0, 16), st_ino=41226, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1633239954 /* 2021-10-03T16:45:54.059362409+1100 */, st_atime_nsec=59362409, st_mtime=1633239954 /* 2021-10-03T16:45:54.059362409+1100 */, st_mtime_nsec=59362409, st_ctime=1633239954 /* 2021-10-03T16:45:54.059362409+1100 */, st_ctime_nsec=59362409}) = 0
8676  ioctl(5, TCGETS, 0x7fe2fba8e0)    = -1 ENOTTY (Inappropriate ioctl for device)
8676  lseek(5, 0, SEEK_CUR)             = 0
8676  write(5, "mouse demo function", 19) = 19
8676  close(5)                          = 0
8676  openat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/configs/c.1/MaxPower", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 5
8676  fstat(5, {st_dev=makedev(0, 16), st_ino=39824, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1633239954 /* 2021-10-03T16:45:54.059362409+1100 */, st_atime_nsec=59362409, st_mtime=1633239954 /* 2021-10-03T16:45:54.059362409+1100 */, st_mtime_nsec=59362409, st_ctime=1633239954 /* 2021-10-03T16:45:54.059362409+1100 */, st_ctime_nsec=59362409}) = 0
8676  ioctl(5, TCGETS, 0x7fe2fbaab0)    = -1 ENOTTY (Inappropriate ioctl for device)
8676  lseek(5, 0, SEEK_CUR)             = 0
8676  write(5, "500", 3)                = 3
8676  close(5)                          = 0
8676  mkdirat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/functions/ffs.usb0", 0777) = 0
8676  rt_sigaction(SIGTERM, {sa_handler=0x61a0f0, sa_mask=[], sa_flags=0}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
8676  getcwd("/home/xxx/Projects/python-functionfs/examples/hid", 1024) = 51
8676  getpid()                          = 8676
8676  getrandom("\xf4\x42\xf1\xb8\xe2\x16\x72\x26\xda\xc1\x03\xa8\x9d\x1d\x40\xe1\xc0\xa7\x40\x37\xbb\x5c\xd1\xa5\x7c\xe5\xc0\x6f\x00\xcc\xc1\x66"..., 2496, GRND_NONBLOCK) = 2496
8676  getrandom("\xfb\x3a\xe8\x53\x0d\xe8\xe8\x5a\x24\x00\xb9\xf8\x54\x05\x4c\x35\xc3\x70\x03\x0e\x58\x6a\x09\xff\x60\x41\xa1\x37\xfb\x5f\xea\x8c"..., 2496, GRND_NONBLOCK) = 2496
8676  openat(AT_FDCWD, "/tmp/sy8tj31f", O_RDWR|O_CREAT|O_EXCL|O_NOFOLLOW|O_CLOEXEC, 0600) = 5
8676  fstat(5, {st_dev=makedev(179, 1), st_ino=677729, st_mode=S_IFREG|0600, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1633239954 /* 2021-10-03T16:45:54.059362409+1100 */, st_atime_nsec=59362409, st_mtime=1633239954 /* 2021-10-03T16:45:54.059362409+1100 */, st_mtime_nsec=59362409, st_ctime=1633239954 /* 2021-10-03T16:45:54.059362409+1100 */, st_ctime_nsec=59362409}) = 0
8676  ioctl(5, TCGETS, 0x7fe2fb9f50)    = -1 ENOTTY (Inappropriate ioctl for device)
8676  lseek(5, 0, SEEK_CUR)             = 0
8676  write(5, "blat", 4)               = 4
8676  close(5)                          = 0
8676  unlinkat(AT_FDCWD, "/tmp/sy8tj31f", 0) = 0
8676  getpid()                          = 8676
8676  getrandom("\xbd\x3a\x94\x2a\xed\x79\x3a\x06\x74\x4f\x1a\x97\xc5\xb3\xdc\x02\x74\x7c\xc7\xaf\xd2\x0b\x7f\x78\xf0\xa8\xe2\x3a\xd0\xbe\xad\x97"..., 2496, GRND_NONBLOCK) = 2496
8676  getrandom("\x81\x6d\xa6\xa1\x36\xda\x17\xa3\x17\xdc\xf5\x22\xa1\x46\x86\xcf\x9c\x72\x15\xfd\x0e\x63\xe8\xd1\x32\x7e\x9f\x3c\x63\xe0\x3b\xa1"..., 2496, GRND_NONBLOCK) = 2496
8676  mkdirat(AT_FDCWD, "/tmp/ffs.usb0_7c2zrpkn", 0700) = 0
8676  mount("usb0", "/tmp/ffs.usb0_7c2zrpkn", "functionfs", 0, "") = 0
8676  clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f8ba6a0e0) = 8680
8676  close(4)                          = 0
8676  symlinkat("/sys/kernel/config/usb_gadget/testusb/functions/ffs.usb0", AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/configs/c.1/function.0") = 0
8676  fstat(3, {st_dev=makedev(0, 10), st_ino=41212, st_mode=S_IFIFO|0600, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1633239954 /* 2021-10-03T16:45:54.055362371+1100 */, st_atime_nsec=55362371, st_mtime=1633239954 /* 2021-10-03T16:45:54.055362371+1100 */, st_mtime_nsec=55362371, st_ctime=1633239954 /* 2021-10-03T16:45:54.055362371+1100 */, st_ctime_nsec=55362371}) = 0
8676  ioctl(3, TCGETS, 0x7fe2fba800)    = -1 ENOTTY (Inappropriate ioctl for device)
8676  read(3,  <unfinished ...>
8680  set_robust_list(0x7f8ba6a0f0, 24) = 0
8680  getpid()                          = 8680
8680  close(3)                          = 0
8680  chdir("/")                        = 0
8680  eventfd2(0, EFD_NONBLOCK)         = 3
8680  fstat(3, {st_dev=makedev(0, 11), st_ino=9166, st_mode=0600, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=0, st_atime=0 /* 1970-01-01T10:00:00.523999999+1000 */, st_atime_nsec=523999999, st_mtime=1633239900 /* 2021-10-03T16:45:00.134821552+1100 */, st_mtime_nsec=134821552, st_ctime=1633239900 /* 2021-10-03T16:45:00.134821552+1100 */, st_ctime_nsec=134821552}) = 0
8680  ioctl(3, TCGETS, 0x7fe2fb9270)    = -1 ENOTTY (Inappropriate ioctl for device)
8680  io_setup(32, [0x7f8ba2a000])      = 0
8680  openat(AT_FDCWD, "/tmp/ffs.usb0_7c2zrpkn/ep0", O_RDWR|O_CLOEXEC) = 5
8680  fstat(5, {st_dev=makedev(0, 44), st_ino=39827, st_mode=S_IFREG|0600, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1633239954 /* 2021-10-03T16:45:54.063362448+1100 */, st_atime_nsec=63362448, st_mtime=1633239954 /* 2021-10-03T16:45:54.063362448+1100 */, st_mtime_nsec=63362448, st_ctime=1633239954 /* 2021-10-03T16:45:54.063362448+1100 */, st_ctime_nsec=63362448}) = 0
8680  write(5, "\3\0\0\0J\0\0\0#\0\0\0\3\0\0\0\3\0\0\0\3\0\0\0\t\4\0\0\1\3\0\0"..., 74) = 74
8680  write(5, "\2\0\0\0\20\0\0\0\0\0\0\0\0\0\0\0", 16) = 16
8680  openat(AT_FDCWD, "/tmp/ffs.usb0_7c2zrpkn/ep1", O_RDWR|O_CLOEXEC) = 6
8680  fstat(6, {st_dev=makedev(0, 44), st_ino=39830, st_mode=S_IFREG|0600, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1633239954 /* 2021-10-03T16:45:54.079362602+1100 */, st_atime_nsec=79362602, st_mtime=1633239954 /* 2021-10-03T16:45:54.079362602+1100 */, st_mtime_nsec=79362602, st_ctime=1633239954 /* 2021-10-03T16:45:54.079362602+1100 */, st_ctime_nsec=79362602}) = 0
8680  fcntl(5, F_GETFL)                 = 0x20002 (flags O_RDWR|O_LARGEFILE)
8680  fcntl(5, F_SETFL, O_RDWR|O_NONBLOCK|O_LARGEFILE) = 0
8680  write(4, "ready", 5 <unfinished ...>
8676  <... read resumed> "ready", 5)    = 5
8680  <... write resumed> )             = 5
8676  close(3 <unfinished ...>
8680  epoll_create1(EPOLL_CLOEXEC <unfinished ...>
8676  <... close resumed> )             = 0
8680  <... epoll_create1 resumed> )     = 7
8680  epoll_ctl(7, EPOLL_CTL_ADD, 3, {EPOLLIN, {u32=3, u64=545460846595}} <unfinished ...>
8676  openat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/UDC", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666 <unfinished ...>
8680  <... epoll_ctl resumed> )         = 0
8676  <... openat resumed> )            = 3
8680  epoll_pwait(7,  <unfinished ...>
8676  fstat(3, {st_dev=makedev(0, 16), st_ino=40677, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1633239954 /* 2021-10-03T16:45:54.083362641+1100 */, st_atime_nsec=83362641, st_mtime=1633239954 /* 2021-10-03T16:45:54.083362641+1100 */, st_mtime_nsec=83362641, st_ctime=1633239954 /* 2021-10-03T16:45:54.083362641+1100 */, st_ctime_nsec=83362641}) = 0
8676  ioctl(3, TCGETS, 0x7fe2fbac80)    = -1 ENOTTY (Inappropriate ioctl for device)
8676  lseek(3, 0, SEEK_CUR)             = 0
8676  ioctl(3, TCGETS, 0x7fe2fbac80)    = -1 ENOTTY (Inappropriate ioctl for device)
8676  lseek(3, 0, SEEK_CUR)             = 0
8676  lseek(3, 0, SEEK_CUR)             = 0
8676  write(3, "700d0000.xudc", 13 <unfinished ...>
8680  <... epoll_pwait resumed> [{EPOLLIN, {u32=3, u64=545460846595}}], 1023, -1, NULL, 8) = 1
8680  read(3, "\1\0\0\0\0\0\0\0", 8)    = 8
8680  io_getevents(0x7f8ba2a000, 0, 32, [], NULL) = 0
8680  read(5,  <unfinished ...>
8676  <... write resumed> )             = 13
8680  <... read resumed> "\0\0\0\0\0\0\0\0\0\0\0\0", 48) = 12
8676  close(3 <unfinished ...>
8680  epoll_pwait(7,  <unfinished ...>
8676  <... close resumed> )             = 0
8676  rt_sigaction(SIGCHLD, {sa_handler=0x61a0f0, sa_mask=[], sa_flags=0}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
8676  rt_sigaction(SIGINT, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=0}, {sa_handler=0x61a0f0, sa_mask=[], sa_flags=0}, 8) = 0
8676  write(1, "Gadget ready, waiting for functi"..., 44) = 44
8676  ppoll(NULL, 0, NULL, NULL, 8823480 <unfinished ...>
8680  <... epoll_pwait resumed> [{EPOLLIN, {u32=3, u64=545460846595}}], 1023, -1, NULL, 8) = 1
8680  read(3, "\2\0\0\0\0\0\0\0", 8)    = 8
8680  io_getevents(0x7f8ba2a000, 0, 32, [], NULL) = 0
8680  read(5, "\0\0\0\0\0\0\0\0\2\0\0\0!\n\0\0\0\0\0\0\4\0\0\0", 48) = 24
8680  write(1, "onEnable called\n", 16) = 16
8680  io_submit(0x7f8ba2a000, 1, [{aio_lio_opcode=IOCB_CMD_PWRITEV, aio_fildes=6, aio_buf=[{iov_base="\0\0\0", iov_len=3}], aio_offset=0, aio_resfd=3}]) = 1
8680  write(5, "", 0)                   = -1 EL2HLT (Level 2 halted)
8680  epoll_pwait(7, [{EPOLLIN, {u32=3, u64=545460846595}}], 1023, -1, NULL, 8) = 1
8680  read(3, "\1\0\0\0\0\0\0\0", 8)    = 8
8680  io_getevents(0x7f8ba2a000, 0, 32, [], NULL) = 0
8680  read(5, "\0\0\0\0\0\0\0\0\5\0\0\0", 48) = 12
8680  epoll_pwait(7, [{EPOLLIN, {u32=3, u64=545460846595}}], 1023, -1, NULL, 8) = 1
8680  read(3, "\2\0\0\0\0\0\0\0", 8)    = 8
8680  io_getevents(0x7f8ba2a000, 0, 32, [{data=0, obj=0x7f8ac407b0, res=-108, res2=-108}], NULL) = 1
8680  read(5, "\0\0\0\0\0\0\0\0\3\0\0\0", 48) = 12
8680  epoll_pwait(7, [{EPOLLIN, {u32=3, u64=545460846595}}], 1023, -1, NULL, 8) = 1
8680  read(3, "\2\0\0\0\0\0\0\0", 8)    = 8
8680  io_getevents(0x7f8ba2a000, 0, 32, [], NULL) = 0
8680  read(5, "\0\0\0\0\0\0\0\0\2\0\0\0!\n\0\0\0\0\0\0\4\0\0\0", 48) = 24
8680  write(1, "onEnable called\n", 16) = 16
8680  io_submit(0x7f8ba2a000, 1, [{aio_lio_opcode=IOCB_CMD_PWRITEV, aio_fildes=6, aio_buf=[{iov_base="\0\0\0", iov_len=3}], aio_offset=0, aio_resfd=3}]) = 1
8680  write(5, "", 0)                   = -1 EL2HLT (Level 2 halted)
8680  epoll_pwait(7, [{EPOLLIN, {u32=3, u64=545460846595}}], 1023, -1, NULL, 8) = 1
8680  read(3, "\1\0\0\0\0\0\0\0", 8)    = 8
8680  io_getevents(0x7f8ba2a000, 0, 32, [], NULL) = 0
8680  read(5, "\0\0\0\0\0\0\0\0\5\0\0\0", 48) = 12
8680  epoll_pwait(7, [{EPOLLIN, {u32=3, u64=545460846595}}], 1023, -1, NULL, 8) = 1
8680  read(3, "\2\0\0\0\0\0\0\0", 8)    = 8
8680  io_getevents(0x7f8ba2a000, 0, 32, [{data=0, obj=0x7f8ac407f0, res=-108, res2=-108}], NULL) = 1
8680  read(5, "\0\0\0\0\0\0\0\0\3\0\0\0", 48) = 12
8680  epoll_pwait(7, 0x3ec2a6c0, 1023, -1, NULL, 8) = -1 EINTR (Interrupted system call)
8676  <... ppoll resumed> )             = ? ERESTARTNOHAND (To be restarted if no handler)
8680  --- SIGINT {si_signo=SIGINT, si_code=SI_KERNEL} ---
8676  --- SIGINT {si_signo=SIGINT, si_code=SI_KERNEL} ---
8680  getpid( <unfinished ...>
8676  ppoll(NULL, 0, NULL, NULL, 8823480 <unfinished ...>
8680  <... getpid resumed> )            = 8680
8680  rt_sigreturn({mask=[]})           = -1 EINTR (Interrupted system call)
8680  close(7)                          = 0
8680  close(6)                          = 0
8680  close(5)                          = 0
8680  close(4)                          = 0
8680  exit_group(0)                     = ?
8680  +++ exited with 0 +++
8676  <... ppoll resumed> )             = ? ERESTARTNOHAND (To be restarted if no handler)
8676  --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=8680, si_uid=0, si_status=0, si_utime=0, si_stime=2} ---
8676  getpid()                          = 8676
8676  rt_sigreturn({mask=[]})           = -1 EINTR (Interrupted system call)
8676  write(1, "Gadget exiting.\n", 16) = 16
8676  rt_sigaction(SIGINT, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=0}, 8) = 0
8676  rt_sigaction(SIGCHLD, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, {sa_handler=0x61a0f0, sa_mask=[], sa_flags=0}, 8) = 0
8676  openat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/UDC", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 3
8676  fstat(3, {st_dev=makedev(0, 16), st_ino=41264, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1633239954 /* 2021-10-03T16:45:54.083362641+1100 */, st_atime_nsec=83362641, st_mtime=1633239976 /* 2021-10-03T16:46:16.807578766+1100 */, st_mtime_nsec=807578766, st_ctime=1633239976 /* 2021-10-03T16:46:16.807578766+1100 */, st_ctime_nsec=807578766}) = 0
8676  ioctl(3, TCGETS, 0x7fe2fbad70)    = -1 ENOTTY (Inappropriate ioctl for device)
8676  lseek(3, 0, SEEK_CUR)             = 0
8676  close(3)                          = 0
8676  kill(8680, SIGINT)                = 0
8676  wait4(8680, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 8680
8676  umount2("/tmp/ffs.usb0_7c2zrpkn", 0) = 0
8676  unlinkat(AT_FDCWD, "/tmp/ffs.usb0_7c2zrpkn", AT_REMOVEDIR) = 0
8676  unlinkat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/configs/c.1/function.0", 0) = 0
8676  unlinkat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/functions/ffs.usb0", AT_REMOVEDIR) = 0
8676  unlinkat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/configs/c.1/strings/0x409", AT_REMOVEDIR) = 0
8676  unlinkat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/configs/c.1", AT_REMOVEDIR) = 0
8676  unlinkat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/strings/0x409", AT_REMOVEDIR) = 0
8676  unlinkat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb", AT_REMOVEDIR) = 0

These lines look a bit sus during a write out to the host - looks like the endpoint didnt set up correctly and configfs is halting internally? 8680 write(5, "", 0) = -1 EL2HLT (Level 2 halted)

I.e from configfs souce

/* FFS_SETUP_PENDING */
if (!(ffs->ev.setup.bRequestType & USB_DIR_IN)) {
  spin_unlock_irq(&ffs->ev.waitq.lock);
  ret = __ffs_ep0_stall(ffs);
  break;
}

and

case FFS_SETUP_PENDING:
        if (ffs->ev.setup.bRequestType & USB_DIR_IN) {
            spin_unlock_irq(&ffs->ev.waitq.lock);
            ret = __ffs_ep0_stall(ffs);
            goto done_mutex;
        }

Hey I also had a thought - is the device maybe trying to negotiate at ss speeds and there is maybe a problem in that area? Cant imagine its used much. I'm trying to look at anything unusual that may be related to the usb chipset and ss speeds fit that idea. It's the iconfiguration error that you highlighted earlier (that i'm guessing to find a reason for) and could be related? Hardware should only be usb2.

vpelletier commented 2 years ago

I downloaded the kernel source and went through the configuration carefully. Configfs is on as expected BUT CONFIG_USB_CONFIGFS_F_HID was not set - this means that HID was not a valid fs overlay (hid.usb0 folder).

True, although it may not actually mean much to my HID example: this example uses functionfs, which is separate from all in-kernel implementations: it special feature is precisely to allow implementing the function in userland instead. In this sense, my HID example is kind of duplicating the in-kernel implementation, ideally granting more flexibility to the developer over what HID reports get sent than the in-kernel implementation would. But it is mainly intended as an example of how to implement functions in userland in a very visual way: virtually any OS will have a USB mouse driver, while an echo example would require a lot more effort to get to the "yes, this device I plugged did run some code". With this HID example, the expected experience is: plug, mouse pointer moves, success.

Except when it's not.

These lines look a bit sus during a write out to the host

They are actually the SET_IDLE requests which also appeared in the usbmon output... Surprisingly, they appear twice here (the !\n read from file descriptor 5 is the 21 0a in usbmon output, which means SET_IDLE) while they appeared only once in the usbmon output, and the GET_DESCRIPTOR request (81 06) does not appear at all.

These SET_IDLE requests ending in a stall should be fine, as they are supposed to be optional. And either way, the SET_IDLE arguments just ask the device to only send a report when it has something to report - which in the case of this sample is always: it it always moving the mouse one position to the right. Which it will do as fast as the host will poll it for new reports. But of course, the host does not know that...

I'm puzzled as to why the GET_DESCRIPTOR request event does not appear here. It would mean the kernel somehow decided it had to reply to it on its own, without telling the userland process. But looking at the v4.9 version of f_fs.c it should really not: the 1 in 81 means it is targeting the interface, just like the one in 21. Of course, I do not have any patch nvidia could have hypothetically applied, I am only reading the vanilla v4.9 code... But I would be very surprised if nvidia has fiddled with this code: surely, they would not have bothered about the USB stack (especially the gadget part of it) on a board whose vendor-specific part (if I understand properly) is the AI accelerator for image processing.

Could you do a similar strace capture while plugging the board to a windows host ?

If you can see a GET_DESCRIPTOR here (which should look something like \201\6\0\0\0\0\02\4\0\0\0), then it means the Linux host is doing something funny.

vpelletier commented 2 years ago

...and I spotted something on the usbmon output: timestamps.

ffff89f472f4db40 2588246878 S Co:2:010:0 s 21 0a 0000 0000 0000 0
ffff89f472f4db40 2588249233 C Co:2:010:0 -32 0
ffff89f472f4db40 2588249295 S Ci:2:010:0 s 81 06 2200 0000 0032 50 <
ffff89f472f4db40 2593385581 C Ci:2:010:0 -2 0
>>> 2588249233-2588246878
2355
>>> 2593385581-2588249295
5136286

The -32 error happened in 2.3ms. The -2 error happened in 5.1s. This is a timeout, and explains why it does not appear in the strace: the device somehow never received it.

Which brings me back to the device driver: USB STALL response behaves in a special way on endpoint zero: it self-clears. On any other endpoint, a halt condition (which signals to the host that the device is somehow very unhappy - typically as a result of some sort of protocol desynchonisation - and stops talking to the host on such endpoint by always replying with a STALL response) must be explicitly cleared by the host (so it can properly re-synchronise with the device). But to do so it needs to issue a standard CLEAR_FEATURE request to the device... Request which of course is sent to the control endpoint: endpoint zero. This is why EP0 must auto-clear the halt condition after sending a STALL response to any stage of a SETUP transaction.

If I were a gambling man, I would bet that the UDC (either the module or the chip, I'm not well versed enough to know whose responsibility this is) does not clear the stall condition on EP0 right after it sent one STALL response to the host. Then, it ignores anything the host is sending it on EP0... Things like HID descriptor requests. And also string descriptor requests.

So, a workaround would be to implement the SET_IDLE request. And then maybe another one, until there is no STALL left and the device never goes deaf. But this is really not a clean solution: eventually a host will send an unsupported request, and the only appropriate response will be a STALL.

EDIT: finished a few thoughts

KiwiLostInMelb commented 2 years ago

Windows output - I changed the report to no movement.

8719  mkdirat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/strings/0x409", 0777) = 0
8719  openat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/strings/0x409/product", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 5
8719  fstat(5, {st_dev=makedev(0, 16), st_ino=42448, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1633295984 /* 2021-10-04T08:19:44.419787248+1100 */, st_atime_nsec=419787248, st_mtime=1633295984 /* 2021-10-04T08:19:44.419787248+1100 */, st_mtime_nsec=419787248, st_ctime=1633295984 /* 2021-10-04T08:19:44.419787248+1100 */, st_ctime_nsec=419787248}) = 0
8719  ioctl(5, TCGETS, 0x7fd54a7b40)    = -1 ENOTTY (Inappropriate ioctl for device)
8719  lseek(5, 0, SEEK_CUR)             = 0
8719  write(5, "HID mouse demo", 14)    = 14
8719  close(5)                          = 0
8719  openat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/strings/0x409/manufacturer", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 5
8719  fstat(5, {st_dev=makedev(0, 16), st_ino=42449, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1633295984 /* 2021-10-04T08:19:44.419787248+1100 */, st_atime_nsec=419787248, st_mtime=1633295984 /* 2021-10-04T08:19:44.419787248+1100 */, st_mtime_nsec=419787248, st_ctime=1633295984 /* 2021-10-04T08:19:44.419787248+1100 */, st_ctime_nsec=419787248}) = 0
8719  ioctl(5, TCGETS, 0x7fd54a7b40)    = -1 ENOTTY (Inappropriate ioctl for device)
8719  lseek(5, 0, SEEK_CUR)             = 0
8719  write(5, "python-functionfs", 17) = 17
8719  close(5)                          = 0
8719  openat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/idVendor", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 5
8719  fstat(5, {st_dev=makedev(0, 16), st_ino=42450, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1633295984 /* 2021-10-04T08:19:44.419787248+1100 */, st_atime_nsec=419787248, st_mtime=1633295984 /* 2021-10-04T08:19:44.419787248+1100 */, st_mtime_nsec=419787248, st_ctime=1633295984 /* 2021-10-04T08:19:44.419787248+1100 */, st_ctime_nsec=419787248}) = 0
8719  ioctl(5, TCGETS, 0x7fd54a7d10)    = -1 ENOTTY (Inappropriate ioctl for device)
8719  lseek(5, 0, SEEK_CUR)             = 0
8719  write(5, "0x1d6b", 6)             = 6
8719  close(5)                          = 0
8719  openat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/idProduct", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 5
8719  fstat(5, {st_dev=makedev(0, 16), st_ino=42451, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1633295984 /* 2021-10-04T08:19:44.419787248+1100 */, st_atime_nsec=419787248, st_mtime=1633295984 /* 2021-10-04T08:19:44.419787248+1100 */, st_mtime_nsec=419787248, st_ctime=1633295984 /* 2021-10-04T08:19:44.419787248+1100 */, st_ctime_nsec=419787248}) = 0
8719  ioctl(5, TCGETS, 0x7fd54a7d10)    = -1 ENOTTY (Inappropriate ioctl for device)
8719  lseek(5, 0, SEEK_CUR)             = 0
8719  write(5, "0x104", 5)              = 5
8719  close(5)                          = 0
8719  mkdirat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/configs/c.1", 0777) = 0
8719  mkdirat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/configs/c.1/strings/0x409", 0777) = 0
8719  openat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/configs/c.1/strings/0x409/configuration", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 5
8719  fstat(5, {st_dev=makedev(0, 16), st_ino=42455, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1633295984 /* 2021-10-04T08:19:44.423787255+1100 */, st_atime_nsec=423787255, st_mtime=1633295984 /* 2021-10-04T08:19:44.423787255+1100 */, st_mtime_nsec=423787255, st_ctime=1633295984 /* 2021-10-04T08:19:44.423787255+1100 */, st_ctime_nsec=423787255}) = 0
8719  ioctl(5, TCGETS, 0x7fd54a7b40)    = -1 ENOTTY (Inappropriate ioctl for device)
8719  lseek(5, 0, SEEK_CUR)             = 0
8719  write(5, "mouse demo function", 19) = 19
8719  close(5)                          = 0
8719  openat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/configs/c.1/MaxPower", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 5
8719  fstat(5, {st_dev=makedev(0, 16), st_ino=42456, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1633295984 /* 2021-10-04T08:19:44.423787255+1100 */, st_atime_nsec=423787255, st_mtime=1633295984 /* 2021-10-04T08:19:44.423787255+1100 */, st_mtime_nsec=423787255, st_ctime=1633295984 /* 2021-10-04T08:19:44.423787255+1100 */, st_ctime_nsec=423787255}) = 0
8719  ioctl(5, TCGETS, 0x7fd54a7d10)    = -1 ENOTTY (Inappropriate ioctl for device)
8719  lseek(5, 0, SEEK_CUR)             = 0
8719  write(5, "500", 3)                = 3
8719  close(5)                          = 0
8719  mkdirat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/functions/ffs.usb0", 0777) = 0
8719  rt_sigaction(SIGTERM, {sa_handler=0x61a0f0, sa_mask=[], sa_flags=0}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
8719  getcwd("/home/piet/Projects/python-functionfs/examples/hid", 1024) = 51
8719  getpid()                          = 8719
8719  getrandom("\xa2\xda\xb1\x4a\x10\x97\x66\xf0\x37\x5f\x06\xd4\xa5\x91\x07\x71\xd6\x1e\xbb\xe8\x4b\xab\x28\xc6\x58\xbb\xb3\xc9\x69\xe8\xc8\xc3"..., 2496, GRND_NONBLOCK) = 2496
8719  getrandom("\x15\xf8\x1b\xe2\x62\x7a\x37\x04\xf8\x9a\x4c\xbb\xdc\x05\x33\xf0\x59\xc6\x27\xe1\x22\x2e\x07\x55\xba\x36\x33\x60\x1f\xdf\xa1\xd3"..., 2496, GRND_NONBLOCK) = 2496
8719  openat(AT_FDCWD, "/tmp/vsgjg_mv", O_RDWR|O_CREAT|O_EXCL|O_NOFOLLOW|O_CLOEXEC, 0600) = 5
8719  fstat(5, {st_dev=makedev(179, 1), st_ino=656664, st_mode=S_IFREG|0600, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1633295984 /* 2021-10-04T08:19:44.423787255+1100 */, st_atime_nsec=423787255, st_mtime=1633295984 /* 2021-10-04T08:19:44.423787255+1100 */, st_mtime_nsec=423787255, st_ctime=1633295984 /* 2021-10-04T08:19:44.423787255+1100 */, st_ctime_nsec=423787255}) = 0
8719  ioctl(5, TCGETS, 0x7fd54a71b0)    = -1 ENOTTY (Inappropriate ioctl for device)
8719  lseek(5, 0, SEEK_CUR)             = 0
8719  write(5, "blat", 4)               = 4
8719  close(5)                          = 0
8719  unlinkat(AT_FDCWD, "/tmp/vsgjg_mv", 0) = 0
8719  getpid()                          = 8719
8719  getrandom("\x6f\xbe\x2c\xa8\x3a\xbc\x3e\x39\x7e\x29\x05\xff\xfc\x55\xa6\x3a\x8a\x88\x07\x2d\x91\x1f\xe0\x9e\x6c\xe6\xb6\xf2\xf3\x93\xee\xd6"..., 2496, GRND_NONBLOCK) = 2496
8719  getrandom("\x48\xbd\x4b\x40\x45\x02\x80\x5f\x3a\x02\xce\xca\x22\x53\x18\x7d\x0c\x85\xcb\xa4\x39\xa0\xdb\xbe\xd5\xdb\x01\x1e\x19\xc8\xe0\xea"..., 2496, GRND_NONBLOCK) = 2496
8719  mkdirat(AT_FDCWD, "/tmp/ffs.usb0_76wfessh", 0700) = 0
8719  mount("usb0", "/tmp/ffs.usb0_76wfessh", "functionfs", 0, "") = 0
8719  clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f99fa80e0) = 8724
8719  close(4)                          = 0
8719  symlinkat("/sys/kernel/config/usb_gadget/testusb/functions/ffs.usb0", AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/configs/c.1/function.0") = 0
8719  fstat(3, {st_dev=makedev(0, 10), st_ino=42441, st_mode=S_IFIFO|0600, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1633295984 /* 2021-10-04T08:19:44.419787248+1100 */, st_atime_nsec=419787248, st_mtime=1633295984 /* 2021-10-04T08:19:44.419787248+1100 */, st_mtime_nsec=419787248, st_ctime=1633295984 /* 2021-10-04T08:19:44.419787248+1100 */, st_ctime_nsec=419787248}) = 0
8719  ioctl(3, TCGETS, 0x7fd54a7a60)    = -1 ENOTTY (Inappropriate ioctl for device)
8719  read(3,  <unfinished ...>
8724  set_robust_list(0x7f99fa80f0, 24) = 0
8724  getpid()                          = 8724
8724  close(3)                          = 0
8724  chdir("/")                        = 0
8724  eventfd2(0, EFD_NONBLOCK)         = 3
8724  fstat(3, {st_dev=makedev(0, 11), st_ino=8276, st_mode=0600, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=0, st_atime=0 /* 1970-01-01T10:00:00.531999999+1000 */, st_atime_nsec=531999999, st_mtime=1633295971 /* 2021-10-04T08:19:31.887750219+1100 */, st_mtime_nsec=887750219, st_ctime=1633295971 /* 2021-10-04T08:19:31.887750219+1100 */, st_ctime_nsec=887750219}) = 0
8724  ioctl(3, TCGETS, 0x7fd54a64d0)    = -1 ENOTTY (Inappropriate ioctl for device)
8724  io_setup(32, [0x7f99f68000])      = 0
8724  openat(AT_FDCWD, "/tmp/ffs.usb0_76wfessh/ep0", O_RDWR|O_CLOEXEC) = 5
8724  fstat(5, {st_dev=makedev(0, 44), st_ino=42459, st_mode=S_IFREG|0600, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1633295984 /* 2021-10-04T08:19:44.427787263+1100 */, st_atime_nsec=427787263, st_mtime=1633295984 /* 2021-10-04T08:19:44.427787263+1100 */, st_mtime_nsec=427787263, st_ctime=1633295984 /* 2021-10-04T08:19:44.427787263+1100 */, st_ctime_nsec=427787263}) = 0
8724  write(5, "\3\0\0\0J\0\0\0#\0\0\0\3\0\0\0\3\0\0\0\3\0\0\0\t\4\0\0\1\3\0\0"..., 74) = 74
8724  write(5, "\2\0\0\0\20\0\0\0\0\0\0\0\0\0\0\0", 16) = 16
8724  openat(AT_FDCWD, "/tmp/ffs.usb0_76wfessh/ep1", O_RDWR|O_CLOEXEC) = 6
8724  fstat(6, {st_dev=makedev(0, 44), st_ino=40496, st_mode=S_IFREG|0600, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1633295984 /* 2021-10-04T08:19:44.443787293+1100 */, st_atime_nsec=443787293, st_mtime=1633295984 /* 2021-10-04T08:19:44.443787293+1100 */, st_mtime_nsec=443787293, st_ctime=1633295984 /* 2021-10-04T08:19:44.443787293+1100 */, st_ctime_nsec=443787293}) = 0
8724  fcntl(5, F_GETFL)                 = 0x20002 (flags O_RDWR|O_LARGEFILE)
8724  fcntl(5, F_SETFL, O_RDWR|O_NONBLOCK|O_LARGEFILE) = 0
8724  write(4, "ready", 5 <unfinished ...>
8719  <... read resumed> "ready", 5)    = 5
8724  <... write resumed> )             = 5
8719  close(3 <unfinished ...>
8724  epoll_create1(EPOLL_CLOEXEC <unfinished ...>
8719  <... close resumed> )             = 0
8724  <... epoll_create1 resumed> )     = 7
8724  epoll_ctl(7, EPOLL_CTL_ADD, 3, {EPOLLIN, {u32=3, u64=545460846595}} <unfinished ...>
8719  openat(AT_FDCWD, "/sys/kernel/config/usb_gadget/testusb/UDC", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666 <unfinished ...>
8724  <... epoll_ctl resumed> )         = 0
8719  <... openat resumed> )            = 3
8724  epoll_pwait(7,  <unfinished ...>
8719  fstat(3, {st_dev=makedev(0, 16), st_ino=42461, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=0, st_size=0, st_atime=1633295984 /* 2021-10-04T08:19:44.443787293+1100 */, st_atime_nsec=443787293, st_mtime=1633295984 /* 2021-10-04T08:19:44.443787293+1100 */, st_mtime_nsec=443787293, st_ctime=1633295984 /* 2021-10-04T08:19:44.443787293+1100 */, st_ctime_nsec=443787293}) = 0
8719  ioctl(3, TCGETS, 0x7fd54a7ee0)    = -1 ENOTTY (Inappropriate ioctl for device)
8719  lseek(3, 0, SEEK_CUR)             = 0
8719  ioctl(3, TCGETS, 0x7fd54a7ee0)    = -1 ENOTTY (Inappropriate ioctl for device)
8719  lseek(3, 0, SEEK_CUR)             = 0
8719  lseek(3, 0, SEEK_CUR)             = 0
8719  write(3, "700d0000.xudc", 13 <unfinished ...>
8724  <... epoll_pwait resumed> [{EPOLLIN, {u32=3, u64=545460846595}}], 1023, -1, NULL, 8) = 1
8719  <... write resumed> )             = 13
8724  read(3,  <unfinished ...>
8719  close(3 <unfinished ...>
8724  <... read resumed> "\1\0\0\0\0\0\0\0", 8) = 8
8719  <... close resumed> )             = 0
8719  rt_sigaction(SIGCHLD, {sa_handler=0x61a0f0, sa_mask=[], sa_flags=0}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
8724  io_getevents(0x7f99f68000, 0, 32,  <unfinished ...>
8719  rt_sigaction(SIGINT, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=0},  <unfinished ...>
8724  <... io_getevents resumed> [], NULL) = 0
8719  <... rt_sigaction resumed> {sa_handler=0x61a0f0, sa_mask=[], sa_flags=0}, 8) = 0
8719  write(1, "Gadget ready, waiting for functi"..., 44) = 44
8719  ppoll(NULL, 0, NULL, NULL, 8823480 <unfinished ...>
8724  read(5, "\0\0\0\0\0\0\0\0\0\0\0\0", 48) = 12
8724  epoll_pwait(7, [{EPOLLIN, {u32=3, u64=545460846595}}], 1023, -1, NULL, 8) = 1
8724  read(3, "\2\0\0\0\0\0\0\0", 8)    = 8
8724  io_getevents(0x7f99f68000, 0, 32, [], NULL) = 0
8724  read(5, "\0\0\0\0\0\0\0\0\2\0\0\0!\n\0\0\0\0\0\0\4\0\0\0", 48) = 24
8724  write(1, "onEnable called\n", 16) = 16
8724  io_submit(0x7f99f68000, 1, [{aio_lio_opcode=IOCB_CMD_PWRITEV, aio_fildes=6, aio_buf=[{iov_base="\0\0\0", iov_len=3}], aio_offset=0, aio_resfd=3}]) = 1
8724  write(5, "", 0)                   = -1 EL2HLT (Level 2 halted)
8724  epoll_pwait(7, [{EPOLLIN, {u32=3, u64=545460846595}}], 1023, -1, NULL, 8) = 1
8724  read(3, "\2\0\0\0\0\0\0\0", 8)    = 8
8724  io_getevents(0x7f99f68000, 0, 32, [{data=0, obj=0x7f9917e7f0, res=-108, res2=-108}], NULL) = 1
8724  read(5, "\0\0\0\0\0\0\0\0\3\0\0\0", 48) = 12
8724  epoll_pwait(7, [{EPOLLIN, {u32=3, u64=545460846595}}], 1023, -1, NULL, 8) = 1
8724  read(3, "\1\0\0\0\0\0\0\0", 8)    = 8
8724  io_getevents(0x7f99f68000, 0, 32, [], NULL) = 0
8724  read(5, "\0\0\0\0\0\0\0\0\2\0\0\0\201\6\0\"\0\0r\0\4\0\0\0", 48) = 24
8724  write(1, "onEnable called\n", 16) = 16
8724  io_submit(0x7f99f68000, 1, [{aio_lio_opcode=IOCB_CMD_PWRITEV, aio_fildes=6, aio_buf=[{iov_base="\0\0\0", iov_len=3}], aio_offset=0, aio_resfd=3}]) = 1
8724  write(5, "\5\1\t\2\241\1\t\1\241\0\5\t\31\1)\3\25\0%\1\225\3u\1\201\2\225\1u\5\201\1"..., 50) = 50
8724  epoll_pwait(7, [{EPOLLIN, {u32=3, u64=545460846595}}], 1023, -1, NULL, 8) = 1
8724  read(3, "\1\0\0\0\0\0\0\0", 8)    = 8
8724  io_getevents(0x7f99f68000, 0, 32, [], NULL) = 0
8724  read(5, 0x7f995e6f10, 48)         = -1 EAGAIN (Resource temporarily unavailable)
8724  epoll_pwait(7, [{EPOLLIN, {u32=3, u64=545460846595}}], 1023, -1, NULL, 8) = 1
8724  read(3, "\1\0\0\0\0\0\0\0", 8)    = 8
8724  io_getevents(0x7f99f68000, 0, 32, [{data=0, obj=0x7f9917eab0, res=3, res2=3}], NULL) = 1
8724  io_submit(0x7f99f68000, 1, [{aio_lio_opcode=IOCB_CMD_PWRITEV, aio_fildes=6, aio_buf=[{iov_base="\0\0\0", iov_len=3}], aio_offset=0, aio_resfd=3}]) = 1
8724  read(5, 0x7f995e6f10, 48)         = -1 EAGAIN (Resource temporarily unavailable)
8724  epoll_pwait(7, [{EPOLLIN, {u32=3, u64=545460846595}}], 1023, -1, NULL, 8) = 1
8724  read(3, "\1\0\0\0\0\0\0\0", 8)    = 8
8724  io_getevents(0x7f99f68000, 0, 32, [{data=0, obj=0x7f9917eab0, res=3, res2=3}], NULL) = 1
8724  io_submit(0x7f99f68000, 1, [{aio_lio_opcode=IOCB_CMD_PWRITEV, aio_fildes=6, aio_buf=[{iov_base="\0\0\0", iov_len=3}], aio_offset=0, aio_resfd=3}]) = 1
8724  read(5, 0x7f995e6f10, 48)         = -1 EAGAIN (Resource temporarily unavailable)
8724  epoll_pwait(7, [{EPOLLIN, {u32=3, u64=545460846595}}], 1023, -1, NULL, 8) = 1
8724  read(3, "\1\0\0\0\0\0\0\0", 8)    = 8
8724  io_getevents(0x7f99f68000, 0, 32, [{data=0, obj=0x7f9917eab0, res=3, res2=3}], NULL) = 1
8724  io_submit(0x7f99f68000, 1, [{aio_lio_opcode=IOCB_CMD_PWRITEV, aio_fildes=6, aio_buf=[{iov_base="\0\0\0", iov_len=3}], aio_offset=0, aio_resfd=3}]) = 1
8724  read(5, 0x7f995e6f10, 48)         = -1 EAGAIN (Resource temporarily unavailable)

Seems to diverge here (trying to line them up in diff) Linux: Empty write(5, "", 0) - Does this mean it already failed before this point and the control endpoint is closed?

8680  read(5, "\0\0\0\0\0\0\0\0\2\0\0\0!\n\0\0\0\0\0\0\4\0\0\0", 48) = 24
8680  write(1, "onEnable called\n", 16) = 16
8680  io_submit(0x7f8ba2a000, 1, [{aio_lio_opcode=IOCB_CMD_PWRITEV, aio_fildes=6, aio_buf=[{iov_base="\0\0\0", iov_len=3}], aio_offset=0, aio_resfd=3}]) = 1
8680  write(5, "", 0)                   = -1 EL2HLT (Level 2 halted)
8680  epoll_pwait(7, [{EPOLLIN, {u32=3, u64=545460846595}}], 1023, -1, NULL, 8) = 1
8680  read(3, "\1\0\0\0\0\0\0\0", 8)    = 8

Windows

8724  read(5, "\0\0\0\0\0\0\0\0\2\0\0\0\201\6\0\"\0\0r\0\4\0\0\0", 48) = 24
8724  write(1, "onEnable called\n", 16) = 16
8724  io_submit(0x7f99f68000, 1, [{aio_lio_opcode=IOCB_CMD_PWRITEV, aio_fildes=6, aio_buf=[{iov_base="\0\0\0", iov_len=3}], aio_offset=0, aio_resfd=3}]) = 1
8724  write(5, "\5\1\t\2\241\1\t\1\241\0\5\t\31\1)\3\25\0%\1\225\3u\1\201\2\225\1u\5\201\1"..., 50) = 50
8724  epoll_pwait(7, [{EPOLLIN, {u32=3, u64=545460846595}}], 1023, -1, NULL, 8) = 1
8724  read(3, "\1\0\0\0\0\0\0\0", 8)    = 8

Also difference just beofre onenable Linux:

8680  read(5, "\0\0\0\0\0\0\0\0\2\0\0\0!\n\0\0\0\0\0\0\4\0\0\0", 48) = 24

Windows:

8724  read(5, "\0\0\0\0\0\0\0\0\2\0\0\0\201\6\0\"\0\0r\0\4\0\0\0", 48) = 24
vpelletier commented 2 years ago

Aha !

So Linux, upon getting timeouts, just restarts the whole sequence, while Windows skips the SET_IDLE request (just above the second "onEnable called"):

8724  read(5, "\0\0\0\0\0\0\0\0\2\0\0\0\201\6\0\"\0\0r\0\4\0\0\0", 48) = 24

Here is the \201\6 (GET_DESCRIPTOR) instead of another !\n.

I do not know if this can be considered a (host-side) Linux bug: Linux could be doing better here to avoid putting the device back into a deaf/mute situation, but I think the root responsibility is on the device side: a halt condition should not stop all communications on ep0.

Checking the history of driver/usb/gadget/udc/tegra-xudc.c in the kernel, I see it clears EP0 halt upon receiving a SETUP packet:

static void tegra_xudc_handle_ep0_setup_packet(struct tegra_xudc *xudc,
                                               struct usb_ctrlrequest *ctrl,
                                               u16 seq_num)
{
        int ret;

        xudc->setup_seq_num = seq_num;

        /* Ensure EP0 is unhalted. */
        ep_unhalt(xudc, 0);

but I also notice that this driver was added upstream in 2019. This is a lot more recent than 4.9 . Could the code in this version lack some fixes which made it into vanilla in 2019 ?

KiwiLostInMelb commented 2 years ago

Who knows how Nvidia patched this? I have the kernel source that this device is running. Is there something in particular I can send you?

The above matches what I see in the running source.

static void tegra_xudc_handle_ep0_setup_packet(struct tegra_xudc *xudc,
                                               struct usb_ctrlrequest *ctrl,
                                               u16 seq_num)
{
        int ret;

        xudc->setup_seq_num = seq_num;

        /* Ensure EP0 is unhalted. */
        ep_unhalt(xudc, 0);

        /*
         * On Tegra210, setup packets with sequence numbers 0xfffe or 0xffff
         * are invalid.  Halt EP0 until we get a valid packet.
         */
        if (xudc->soc->invalid_seq_num &&
            (seq_num == 0xfffe || seq_num == 0xffff)) {
                dev_warn(xudc->dev, "invalid sequence number detected\n");
                ep_halt(xudc, 0);
                return;
        }

        if (ctrl->wLength)
                xudc->setup_state = (ctrl->bRequestType & USB_DIR_IN) ?
                        DATA_STAGE_XFER :  DATA_STAGE_RECV;
...etc

This does match the latest kernel source (https://github.com/torvalds/linux/blob/master/drivers/usb/gadget/udc/tegra-xudc.c) in this area only - there are a lot of other differences

vpelletier commented 2 years ago

Mmh, this looks correct indeed. Actually, I have no way to know if the latest vanilla source works any better (maybe the issue is even in-silicon ? I have really very little clue here). So I think the best would be to report the issue to nvidia, ideally providing them with:

(plus the usual context which will mean more to them than to me, like the exact kernel version, maybe kernel .config file, ...)

This should give them all they need to check my conclusions, reproduce the issue and hopefully come up with a fix. Or throw the ball back on my side with something I would be doing wrong...

KiwiLostInMelb commented 2 years ago

Linkback: https://forums.developer.nvidia.com/t/nano-configfs-custom-usb-mouse-device-works-for-a-windows-host-but-not-a-linux-host/190998/20

KiwiLostInMelb commented 2 years ago

FYI - I am recompiling the kernel with the following and will install and see what we get from the dmesg or syslog output.

CONFIG_USB_GADGET_DEBUG_FILES=y CONFIG_USB_GADGET_DEBUG_FS=y

Do you think I need any others?

If I still dont get great messages then I can enable: CONFIG_USB_GADGET_DEBUG=y CONFIG_USB_GADGET_VERBOSE=y But both of these come with a warning about introducing timing errors which could cause other faults - so I'll try the above first.

vpelletier commented 2 years ago

CONFIG_DYNAMIC_DEBUG could be useful as well, to enable more verbose messages in drivers/usb/gadget/udc/tegra_xudc.c and drivers/phy/tegra/xusb.c . See admin-guide/dynamic-debug-howto for how to enable them at runtime and check the output.

KiwiLostInMelb commented 2 years ago

CONFIG_DYNAMIC_DEBUG is already set by default - but when I tested by enabling the configfs module it didnt give me much more info so I am forcing the debug at compile to be sure. Yes I did boot with the debug kernel parameter. Still compiling - about 2 hours left I think.

Dont know if this is the right approach so lets see.

KiwiLostInMelb commented 2 years ago

Hmm debug didnt seem to add messages but dynamic on those files did. I did something wrong but hopefully this is ok... See below

Right at the end I issued a sudo lsusb -vd 1d6b:0104 on the host - failed with the previous errors


[ 6207.777311] extcon-gpio-states extcon:extcon@1: Cable state:1, cable id:1
[ 6207.787439] tegra-xudc-new 700d0000.xudc: vbus state: 1
[ 6207.794091] [hold VBUS wakelock]
[ 6207.797768] tegra-xudc-new 700d0000.xudc: exiting ELPG
[ 6207.803759] tegra-xudc-new 700d0000.xudc: exiting ELPG done
[ 6207.809698] tegra-xudc-new 700d0000.xudc: device mode on: 0
[ 6207.815521] tegra-xusb-padctl 7009f000.xusb_padctl: power on UTMI pads 0
[ 6207.822433] tegra-xudc-new 700d0000.xudc: active: 0 => 1
[ 6208.097024] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821000, lo = 0x1000000, hi = 0x0, status = 0x1000000, control = 0x8801
[ 6208.108774] tegra-xudc-new 700d0000.xudc: PRC, Not PR, PORTSC = 0x220c03
[ 6208.115690] tegra-xudc-new 700d0000.xudc: CSC, PORTSC = 0x20c03
[ 6208.121697] tegra-xudc-new 700d0000.xudc: PORTSC = 0xc03
[ 6208.155046] android_work: did not send uevent (0 0           (null))
[ 6208.161505] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821010, lo = 0x1000680, hi = 0x400000, status = 0x1000000, control = 0xfc01
[ 6208.161612] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea0c0, lo = 0xffd42800, hi = 0x0, status = 0x12, control = 0x10c25
[ 6208.161637] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x0
[ 6208.161692] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821020, lo = 0xffe8e0c0, hi = 0x0, status = 0x1000000, control = 0x8001
[ 6208.161725] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea0c0 -> ffffff800a4ea0c0; trb ffffff800a4ea0c0
[ 6208.161739] tegra-xudc-new 700d0000.xudc: bytes transferred 18 / 18
[ 6208.161756] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f089dd80 on ep 0 with status 0
[ 6208.161794] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea0d0, lo = 0x0, hi = 0x0, status = 0x0, control = 0x1025
[ 6208.161805] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x0
[ 6208.161851] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821030, lo = 0xffe8e0d0, hi = 0x0, status = 0x1000000, control = 0x8001
[ 6208.161868] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea0d0 -> ffffff800a4ea0d0; trb ffffff800a4ea0d0
[ 6208.161881] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 6208.161895] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f79cba80 on ep 0 with status 0
[ 6208.174151] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821040, lo = 0x1000000, hi = 0x0, status = 0x1000000, control = 0x8801
[ 6208.174160] tegra-xudc-new 700d0000.xudc: PRC, Not PR, PORTSC = 0x200c03
[ 6208.174196] tegra-xudc-new 700d0000.xudc: PORTSC = 0xc03
[ 6208.230264] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821050, lo = 0x2b0500, hi = 0x0, status = 0x1000000, control = 0xfc01
[ 6208.230270] tegra-xudc-new 700d0000.xudc: USB_REQ_SET_ADDRESS
[ 6208.230273] tegra-xudc-new 700d0000.xudc: set address: 43
[ 6208.230280] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea0e0, lo = 0x0, hi = 0x0, status = 0x0, control = 0x11025
[ 6208.230282] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x0
[ 6208.230295] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821060, lo = 0xffe8e0e0, hi = 0x0, status = 0x1000000, control = 0x8001
[ 6208.230299] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea0e0 -> ffffff800a4ea0e0; trb ffffff800a4ea0e0
[ 6208.230302] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 6208.230305] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f79cba80 on ep 0 with status 0
[ 6208.246927] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821070, lo = 0x1000680, hi = 0x120000, status = 0x1000001, control = 0xfc01
[ 6208.246947] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea0f0, lo = 0xffd42800, hi = 0x0, status = 0x12, control = 0x10c25
[ 6208.246950] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x10000
[ 6208.246971] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821080, lo = 0xffe8e0f0, hi = 0x0, status = 0x1000000, control = 0x8001
[ 6208.246975] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea0f0 -> ffffff800a4ea0f0; trb ffffff800a4ea0f0
[ 6208.246978] tegra-xudc-new 700d0000.xudc: bytes transferred 18 / 18
[ 6208.246982] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f089dd80 on ep 0 with status 0
[ 6208.246992] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea100, lo = 0x0, hi = 0x0, status = 0x0, control = 0x1025
[ 6208.246994] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x10000
[ 6208.247016] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821090, lo = 0xffe8e100, hi = 0x0, status = 0x1000000, control = 0x8001
[ 6208.247020] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea100 -> ffffff800a4ea100; trb ffffff800a4ea100
[ 6208.247022] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 6208.247025] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f79cba80 on ep 0 with status 0
[ 6208.247099] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8210a0, lo = 0xf000680, hi = 0x50000, status = 0x1000002, control = 0xfc01
[ 6208.247112] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea110, lo = 0xffd42800, hi = 0x0, status = 0x5, control = 0x10c25
[ 6208.247115] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x20000
[ 6208.258840] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8210b0, lo = 0xffe8e110, hi = 0x0, status = 0x1000000, control = 0x8001
[ 6208.258844] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea110 -> ffffff800a4ea110; trb ffffff800a4ea110
[ 6208.258847] tegra-xudc-new 700d0000.xudc: bytes transferred 5 / 5
[ 6208.258850] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f089dd80 on ep 0 with status 0
[ 6208.258859] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea120, lo = 0x0, hi = 0x0, status = 0x0, control = 0x1025
[ 6208.258861] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x20000
[ 6208.258878] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8210c0, lo = 0xffe8e120, hi = 0x0, status = 0x1000000, control = 0x8001
[ 6208.258882] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea120 -> ffffff800a4ea120; trb ffffff800a4ea120
[ 6208.258884] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 6208.258887] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f79cba80 on ep 0 with status 0
[ 6208.270110] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8210d0, lo = 0xf000680, hi = 0x160000, status = 0x1000003, control = 0xfc01
[ 6208.270122] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea130, lo = 0xffd42800, hi = 0x0, status = 0x16, control = 0x10c25
[ 6208.270124] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x30000
[ 6208.270142] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8210e0, lo = 0xffe8e130, hi = 0x0, status = 0x1000000, control = 0x8001
[ 6208.270145] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea130 -> ffffff800a4ea130; trb ffffff800a4ea130
[ 6208.270148] tegra-xudc-new 700d0000.xudc: bytes transferred 22 / 22
[ 6208.270150] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f089dd80 on ep 0 with status 0
[ 6208.270160] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea140, lo = 0x0, hi = 0x0, status = 0x0, control = 0x1025
[ 6208.270162] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x30000
[ 6208.270180] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8210f0, lo = 0xffe8e140, hi = 0x0, status = 0x1000000, control = 0x8001
[ 6208.270183] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea140 -> ffffff800a4ea140; trb ffffff800a4ea140
[ 6208.270186] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 6208.270189] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f79cba80 on ep 0 with status 0
[ 6208.276294] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821100, lo = 0x2000680, hi = 0x90000, status = 0x1000004, control = 0xfc01
[ 6208.276306] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea150, lo = 0xffd42800, hi = 0x0, status = 0x9, control = 0x10c25
[ 6208.276308] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x40000
[ 6208.276326] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821110, lo = 0xffe8e150, hi = 0x0, status = 0x1000000, control = 0x8001
[ 6208.276330] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea150 -> ffffff800a4ea150; trb ffffff800a4ea150
[ 6208.276332] tegra-xudc-new 700d0000.xudc: bytes transferred 9 / 9
[ 6208.276335] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f089dd80 on ep 0 with status 0
[ 6208.276344] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea160, lo = 0x0, hi = 0x0, status = 0x0, control = 0x1025
[ 6208.276346] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x40000
[ 6208.285397] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821120, lo = 0xffe8e160, hi = 0x0, status = 0x1000000, control = 0x8001
[ 6208.285406] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea160 -> ffffff800a4ea160; trb ffffff800a4ea160
[ 6208.285412] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 6208.285420] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f79cba80 on ep 0 with status 0
[ 6208.285430] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821130, lo = 0x2000680, hi = 0x220000, status = 0x1000005, control = 0xfc01
[ 6208.285452] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea170, lo = 0xffd42800, hi = 0x0, status = 0x22, control = 0x10c25
[ 6208.285458] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x50000
[ 6208.285530] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821140, lo = 0xffe8e170, hi = 0x0, status = 0x1000000, control = 0x8001
[ 6208.285540] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea170 -> ffffff800a4ea170; trb ffffff800a4ea170
[ 6208.285548] tegra-xudc-new 700d0000.xudc: bytes transferred 34 / 34
[ 6208.285557] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f089dd80 on ep 0 with status 0
[ 6208.285578] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea180, lo = 0x0, hi = 0x0, status = 0x0, control = 0x1025
[ 6208.285585] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x50000
[ 6208.297292] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821150, lo = 0xffe8e180, hi = 0x0, status = 0x1000000, control = 0x8001
[ 6208.297334] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea180 -> ffffff800a4ea180; trb ffffff800a4ea180
[ 6208.297367] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 6208.297404] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f79cba80 on ep 0 with status 0
[ 6208.297457] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821160, lo = 0x3000680, hi = 0xff0000, status = 0x1000006, control = 0xfc01
[ 6208.297558] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea190, lo = 0xffd42800, hi = 0x0, status = 0x4, control = 0x10c25
[ 6208.297587] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x60000
[ 6208.297656] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821170, lo = 0xffe8e190, hi = 0x0, status = 0x1000000, control = 0x8001
[ 6208.297699] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea190 -> ffffff800a4ea190; trb ffffff800a4ea190
[ 6208.297732] tegra-xudc-new 700d0000.xudc: bytes transferred 4 / 4
[ 6208.297768] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f089dd80 on ep 0 with status 0
[ 6208.297846] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea1a0, lo = 0x0, hi = 0x0, status = 0x0, control = 0x1025
[ 6208.297876] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x60000
[ 6208.298131] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821180, lo = 0xffe8e1a0, hi = 0x0, status = 0x1000000, control = 0x8001
[ 6208.298173] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea1a0 -> ffffff800a4ea1a0; trb ffffff800a4ea1a0
[ 6208.298205] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 6208.298242] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f79cba80 on ep 0 with status 0
[ 6208.298288] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821190, lo = 0x3020680, hi = 0xff0409, status = 0x1000007, control = 0xfc01
[ 6208.298385] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea1b0, lo = 0xffd42800, hi = 0x0, status = 0x1e, control = 0x10c25
[ 6208.298415] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x70000
[ 6208.298481] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8211a0, lo = 0xffe8e1b0, hi = 0x0, status = 0x1000000, control = 0x8001
[ 6208.298522] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea1b0 -> ffffff800a4ea1b0; trb ffffff800a4ea1b0
[ 6208.298556] tegra-xudc-new 700d0000.xudc: bytes transferred 30 / 30
[ 6208.298591] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f089dd80 on ep 0 with status 0
[ 6208.298610] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea1c0, lo = 0x0, hi = 0x0, status = 0x0, control = 0x1025
[ 6208.298612] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x70000
[ 6208.305306] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8211b0, lo = 0xffe8e1c0, hi = 0x0, status = 0x1000000, control = 0x8001
[ 6208.305309] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea1c0 -> ffffff800a4ea1c0; trb ffffff800a4ea1c0
[ 6208.305312] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 6208.305314] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f79cba80 on ep 0 with status 0
[ 6208.305318] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8211c0, lo = 0x3010680, hi = 0xff0409, status = 0x1000008, control = 0xfc01
[ 6208.305328] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea1d0, lo = 0xffd42800, hi = 0x0, status = 0x24, control = 0x10c25
[ 6208.305330] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x80000
[ 6208.310642] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8211d0, lo = 0xffe8e1d0, hi = 0x0, status = 0x1000000, control = 0x8001
[ 6208.310645] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea1d0 -> ffffff800a4ea1d0; trb ffffff800a4ea1d0
[ 6208.310648] tegra-xudc-new 700d0000.xudc: bytes transferred 36 / 36
[ 6208.310651] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f089dd80 on ep 0 with status 0
[ 6208.310659] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea1e0, lo = 0x0, hi = 0x0, status = 0x0, control = 0x1025
[ 6208.310661] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x80000
[ 6208.322229] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8211e0, lo = 0xffe8e1e0, hi = 0x0, status = 0x1000000, control = 0x8001
[ 6208.322240] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea1e0 -> ffffff800a4ea1e0; trb ffffff800a4ea1e0
[ 6208.322248] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 6208.322258] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f79cba80 on ep 0 with status 0
[ 6208.322270] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8211f0, lo = 0x3030680, hi = 0xff0409, status = 0x1000009, control = 0xfc01
[ 6208.322297] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea1f0, lo = 0xffd42800, hi = 0x0, status = 0x22, control = 0x10c25
[ 6208.322305] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x90000
[ 6208.322364] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821200, lo = 0xffe8e1f0, hi = 0x0, status = 0x1000000, control = 0x8001
[ 6208.322375] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea1f0 -> ffffff800a4ea1f0; trb ffffff800a4ea1f0
[ 6208.322384] tegra-xudc-new 700d0000.xudc: bytes transferred 34 / 34
[ 6208.322394] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f089dd80 on ep 0 with status 0
[ 6208.322418] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea200, lo = 0x0, hi = 0x0, status = 0x0, control = 0x1025
[ 6208.322426] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x90000
[ 6208.322448] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821210, lo = 0xffe8e200, hi = 0x0, status = 0x1000000, control = 0x8001
[ 6208.322459] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea200 -> ffffff800a4ea200; trb ffffff800a4ea200
[ 6208.322467] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 6208.322477] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f79cba80 on ep 0 with status 0
[ 6208.328335] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821220, lo = 0x10900, hi = 0x0, status = 0x100000a, control = 0xfc01
[ 6208.328371] tegra-xudc-new 700d0000.xudc: USB_REQ_SET_CONFIGURATION
[ 6208.328410] configfs-gadget gadget: high-speed config #1: c
[ 6208.328496] tegra-xudc-new 700d0000.xudc: ep 3 (type: 3, dir: in) enabled
[ 6208.328638] tegra-xudc-new 700d0000.xudc: tegra_xudc_set_selfpowered: 0
[ 6208.328675] tegra-xudc-new 700d0000.xudc: tegra_xudc_gadget_vbus_draw: 500 mA
[ 6208.328729] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea210, lo = 0x0, hi = 0x0, status = 0x0, control = 0x11025
[ 6208.328760] tegra-xudc-new 700d0000.xudc: ring doorbell: 0xa0000
[ 6208.328812] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821230, lo = 0xffe8e210, hi = 0x0, status = 0x1000000, control = 0x8001
[ 6208.328855] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea210 -> ffffff800a4ea210; trb ffffff800a4ea210
[ 6208.328887] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 6208.328924] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f089dd80 on ep 0 with status 0
[ 6208.329062] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821240, lo = 0x3040680, hi = 0xff0409, status = 0x100000b, control = 0xfc01
[ 6208.329145] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea220, lo = 0xffd42800, hi = 0x0, status = 0x28, control = 0x10c25
[ 6208.329148] tegra-xudc-new 700d0000.xudc: ring doorbell: 0xb0000
[ 6208.329168] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821250, lo = 0xffe8e220, hi = 0x0, status = 0x1000000, control = 0x8001
[ 6208.329171] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea220 -> ffffff800a4ea220; trb ffffff800a4ea220
[ 6208.329174] tegra-xudc-new 700d0000.xudc: bytes transferred 40 / 40
[ 6208.329177] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f089dd80 on ep 0 with status 0
[ 6208.329186] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea230, lo = 0x0, hi = 0x0, status = 0x0, control = 0x1025
[ 6208.329188] tegra-xudc-new 700d0000.xudc: ring doorbell: 0xb0000
[ 6208.329668] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea800, lo = 0xffd418c0, hi = 0x0, status = 0x3, control = 0x421
[ 6208.329671] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x300
[ 6208.334580] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821260, lo = 0xffe8e230, hi = 0x0, status = 0x1000000, control = 0x8001
[ 6208.334584] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea230 -> ffffff800a4ea230; trb ffffff800a4ea230
[ 6208.334586] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 6208.334589] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f79cba80 on ep 0 with status 0
[ 6208.334592] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821270, lo = 0x3030680, hi = 0xff0409, status = 0x100000c, control = 0xfc01
[ 6208.334603] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea240, lo = 0xffd42800, hi = 0x0, status = 0x22, control = 0x10c25
[ 6208.334605] tegra-xudc-new 700d0000.xudc: ring doorbell: 0xc0000
[ 6208.334620] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821280, lo = 0xffe8e240, hi = 0x0, status = 0x1000000, control = 0x8001
[ 6208.334624] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea240 -> ffffff800a4ea240; trb ffffff800a4ea240
[ 6208.334626] tegra-xudc-new 700d0000.xudc: bytes transferred 34 / 34
[ 6208.334629] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f089dd80 on ep 0 with status 0
[ 6208.334638] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea250, lo = 0x0, hi = 0x0, status = 0x0, control = 0x1025
[ 6208.334640] tegra-xudc-new 700d0000.xudc: ring doorbell: 0xc0000
[ 6208.334661] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821290, lo = 0xffe8e250, hi = 0x0, status = 0x1000000, control = 0x8001
[ 6208.334665] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea250 -> ffffff800a4ea250; trb ffffff800a4ea250
[ 6208.334667] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 6208.334670] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f79cba80 on ep 0 with status 0
[ 6208.334733] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8212a0, lo = 0xa21, hi = 0x0, status = 0x100000d, control = 0xfc01
[ 6208.345770] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8212b0, lo = 0x22000681, hi = 0x320000, status = 0x100000e, control = 0xfc01
[ 6209.931748] android_work: sent uevent USB_STATE=CONNECTED
[ 6209.938029] android_work: sent uevent USB_STATE=CONFIGURED
[ 6213.796168] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8212c0, lo = 0x22000681, hi = 0x320000, status = 0x100000f, control = 0xfc01
[ 6218.915881] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8212d0, lo = 0x22000681, hi = 0x320000, status = 0x1000010, control = 0xfc01
[ 6224.035872] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8212e0, lo = 0x22000681, hi = 0x320000, status = 0x1000011, control = 0xfc01
[ 6229.156714] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8212f0, lo = 0x3000680, hi = 0x40000, status = 0x1000012, control = 0xfc01
[ 6230.160440] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821300, lo = 0x22000681, hi = 0x320000, status = 0x1000013, control = 0xfc01
[ 6235.163581] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821310, lo = 0xf000680, hi = 0x50000, status = 0x1000014, control = 0xfc01
[ 6240.167089] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821320, lo = 0xa000680, hi = 0x40000, status = 0x1000015, control = 0xfc01
[ 6245.170385] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821330, lo = 0x80, hi = 0x20000, status = 0x1000016, control = 0xfc01
KiwiLostInMelb commented 2 years ago

Another one with a bit more debugging

[ 4359.497083] extcon-gpio-states extcon:extcon@1: Cable state:1, cable id:1
[ 4359.497699] tegra-xudc-new 700d0000.xudc: vbus state: 1
[ 4359.497780] [hold VBUS wakelock]
[ 4359.497838] tegra-xudc-new 700d0000.xudc: exiting ELPG
[ 4359.510321] tegra-xudc-new 700d0000.xudc: exiting ELPG done
[ 4359.510335] tegra-xudc-new 700d0000.xudc: device mode on: 0
[ 4359.510343] tegra-xusb-padctl 7009f000.xusb_padctl: set vbus override
[ 4359.510352] tegra-xusb-padctl 7009f000.xusb_padctl: 00000c60 > 00211052
[ 4359.510358] tegra-xusb-padctl 7009f000.xusb_padctl: 00000c60 < 00215052
[ 4359.510368] tegra-xusb-padctl 7009f000.xusb_padctl: power on UTMI pads 0
[ 4359.510379] tegra-xusb-padctl 7009f000.xusb_padctl: 00000088 > 04cd1011
[ 4359.510386] tegra-xusb-padctl 7009f000.xusb_padctl: 00000088 < 00cd1011
[ 4359.510393] tegra-xusb-padctl 7009f000.xusb_padctl: 0000008c > 10100044
[ 4359.510399] tegra-xusb-padctl 7009f000.xusb_padctl: 0000008c < 10100040
[ 4359.510406] tegra-xudc-new 700d0000.xudc: active: 0 => 1
[ 4359.510416] tegra-xusb-padctl 7009f000.xusb_padctl: 00000c60 > 0021505b
[ 4359.510423] tegra-xusb-padctl 7009f000.xusb_padctl: USB2_VBUS_ID 0x21505b otg_vbus_on was 0
[ 4359.788114] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821000, lo = 0x1000000, hi = 0x0, status = 0x1000000, control = 0x8801
[ 4359.788163] tegra-xudc-new 700d0000.xudc: PRC, PR, PORTSC = 0x200d30
[ 4359.788217] tegra-xudc-new 700d0000.xudc: PORTSC = 0xa0
[ 4359.798954] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821010, lo = 0x1000000, hi = 0x0, status = 0x1000000, control = 0x8801
[ 4359.798979] tegra-xudc-new 700d0000.xudc: PRC, Not PR, PORTSC = 0x220c03
[ 4359.799061] tegra-xudc-new 700d0000.xudc: CSC, PORTSC = 0x20c03
[ 4359.799088] tegra-xudc-new 700d0000.xudc: PORTSC = 0xc03
[ 4359.799211] android_work: did not send uevent (0 0           (null))
[ 4359.852040] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821020, lo = 0x1000680, hi = 0x400000, status = 0x1000000, control = 0xfc01
[ 4359.852282] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea110, lo = 0xffd38000, hi = 0x0, status = 0x12, control = 0x10c24
[ 4359.852328] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x0
[ 4359.852397] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821030, lo = 0xffe8e110, hi = 0x0, status = 0x1000000, control = 0x8001
[ 4359.852461] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea110 -> ffffff800a4ea110; trb ffffff800a4ea110
[ 4359.852516] tegra-xudc-new 700d0000.xudc: bytes transferred 18 / 18
[ 4359.852573] tegra-xudc-new 700d0000.xudc: completing request ffffffc0ed9f0b40 on ep 0 with status 0
[ 4359.852685] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea120, lo = 0x0, hi = 0x0, status = 0x0, control = 0x1024
[ 4359.852727] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x0
[ 4359.853023] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821040, lo = 0xffe8e120, hi = 0x0, status = 0x1000000, control = 0x8001
[ 4359.853087] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea120 -> ffffff800a4ea120; trb ffffff800a4ea120
[ 4359.853134] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 4359.853184] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f7a9c0c0 on ep 0 with status 0
[ 4359.853764] android_work: sent uevent USB_STATE=CONNECTED
[ 4359.856140] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821050, lo = 0x1000000, hi = 0x0, status = 0x1000000, control = 0x8801
[ 4359.856200] tegra-xudc-new 700d0000.xudc: PRC, PR, PORTSC = 0x200d31
[ 4359.856268] tegra-xudc-new 700d0000.xudc: PORTSC = 0xa0
[ 4359.864057] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821060, lo = 0x1000000, hi = 0x0, status = 0x1000000, control = 0x8801
[ 4359.864067] tegra-xudc-new 700d0000.xudc: PRC, Not PR, PORTSC = 0x200c03
[ 4359.864114] tegra-xudc-new 700d0000.xudc: PORTSC = 0xc03
[ 4359.864200] android_work: sent uevent USB_STATE=DISCONNECTED
[ 4359.916656] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821070, lo = 0x320500, hi = 0x0, status = 0x1000000, control = 0xfc01
[ 4359.916670] tegra-xudc-new 700d0000.xudc: USB_REQ_SET_ADDRESS
[ 4359.916679] tegra-xudc-new 700d0000.xudc: set address: 50
[ 4359.916697] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea130, lo = 0x0, hi = 0x0, status = 0x0, control = 0x11024
[ 4359.916706] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x0
[ 4359.916791] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821080, lo = 0xffe8e130, hi = 0x0, status = 0x1000000, control = 0x8001
[ 4359.916813] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea130 -> ffffff800a4ea130; trb ffffff800a4ea130
[ 4359.916829] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 4359.916847] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f7a9c0c0 on ep 0 with status 0
[ 4359.930657] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821090, lo = 0x1000680, hi = 0x120000, status = 0x1000001, control = 0xfc01
[ 4359.930693] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea140, lo = 0xffd38000, hi = 0x0, status = 0x12, control = 0x10c24
[ 4359.930698] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x10000
[ 4359.930728] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8210a0, lo = 0xffe8e140, hi = 0x0, status = 0x1000000, control = 0x8001
[ 4359.930735] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea140 -> ffffff800a4ea140; trb ffffff800a4ea140
[ 4359.930739] tegra-xudc-new 700d0000.xudc: bytes transferred 18 / 18
[ 4359.930744] tegra-xudc-new 700d0000.xudc: completing request ffffffc0ed9f0b40 on ep 0 with status 0
[ 4359.930758] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea150, lo = 0x0, hi = 0x0, status = 0x0, control = 0x1024
[ 4359.930762] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x10000
[ 4359.930785] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8210b0, lo = 0xffe8e150, hi = 0x0, status = 0x1000000, control = 0x8001
[ 4359.930792] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea150 -> ffffff800a4ea150; trb ffffff800a4ea150
[ 4359.930798] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 4359.930803] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f7a9c0c0 on ep 0 with status 0
[ 4359.930857] android_work: sent uevent USB_STATE=CONNECTED
[ 4359.930977] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8210c0, lo = 0xf000680, hi = 0x50000, status = 0x1000002, control = 0xfc01
[ 4359.931016] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea160, lo = 0xffd38000, hi = 0x0, status = 0x5, control = 0x10c24
[ 4359.931033] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x20000
[ 4359.931091] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8210d0, lo = 0xffe8e160, hi = 0x0, status = 0x1000000, control = 0x8001
[ 4359.931104] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea160 -> ffffff800a4ea160; trb ffffff800a4ea160
[ 4359.931115] tegra-xudc-new 700d0000.xudc: bytes transferred 5 / 5
[ 4359.931128] tegra-xudc-new 700d0000.xudc: completing request ffffffc0ed9f0b40 on ep 0 with status 0
[ 4359.931156] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea170, lo = 0x0, hi = 0x0, status = 0x0, control = 0x1024
[ 4359.931166] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x20000
[ 4359.931216] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8210e0, lo = 0xffe8e170, hi = 0x0, status = 0x1000000, control = 0x8001
[ 4359.931220] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea170 -> ffffff800a4ea170; trb ffffff800a4ea170
[ 4359.931223] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 4359.931227] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f7a9c0c0 on ep 0 with status 0
[ 4359.931296] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8210f0, lo = 0xf000680, hi = 0x160000, status = 0x1000003, control = 0xfc01
[ 4359.931310] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea180, lo = 0xffd38000, hi = 0x0, status = 0x16, control = 0x10c24
[ 4359.931312] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x30000
[ 4359.931331] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821100, lo = 0xffe8e180, hi = 0x0, status = 0x1000000, control = 0x8001
[ 4359.931335] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea180 -> ffffff800a4ea180; trb ffffff800a4ea180
[ 4359.931338] tegra-xudc-new 700d0000.xudc: bytes transferred 22 / 22
[ 4359.931342] tegra-xudc-new 700d0000.xudc: completing request ffffffc0ed9f0b40 on ep 0 with status 0
[ 4359.931351] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea190, lo = 0x0, hi = 0x0, status = 0x0, control = 0x1024
[ 4359.931354] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x30000
[ 4359.931368] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821110, lo = 0xffe8e190, hi = 0x0, status = 0x1000000, control = 0x8001
[ 4359.931372] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea190 -> ffffff800a4ea190; trb ffffff800a4ea190
[ 4359.931374] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 4359.931377] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f7a9c0c0 on ep 0 with status 0
[ 4359.931533] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821120, lo = 0x2000680, hi = 0x90000, status = 0x1000004, control = 0xfc01
[ 4359.931545] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea1a0, lo = 0xffd38000, hi = 0x0, status = 0x9, control = 0x10c24
[ 4359.931548] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x40000
[ 4359.931560] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821130, lo = 0xffe8e1a0, hi = 0x0, status = 0x1000000, control = 0x8001
[ 4359.931564] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea1a0 -> ffffff800a4ea1a0; trb ffffff800a4ea1a0
[ 4359.931567] tegra-xudc-new 700d0000.xudc: bytes transferred 9 / 9
[ 4359.931570] tegra-xudc-new 700d0000.xudc: completing request ffffffc0ed9f0b40 on ep 0 with status 0
[ 4359.931580] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea1b0, lo = 0x0, hi = 0x0, status = 0x0, control = 0x1024
[ 4359.931583] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x40000
[ 4359.931604] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821140, lo = 0xffe8e1b0, hi = 0x0, status = 0x1000000, control = 0x8001
[ 4359.931608] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea1b0 -> ffffff800a4ea1b0; trb ffffff800a4ea1b0
[ 4359.931611] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 4359.931615] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f7a9c0c0 on ep 0 with status 0
[ 4359.931653] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821150, lo = 0x2000680, hi = 0x220000, status = 0x1000005, control = 0xfc01
[ 4359.931665] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea1c0, lo = 0xffd38000, hi = 0x0, status = 0x22, control = 0x10c24
[ 4359.931668] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x50000
[ 4359.931680] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821160, lo = 0xffe8e1c0, hi = 0x0, status = 0x1000000, control = 0x8001
[ 4359.931688] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea1c0 -> ffffff800a4ea1c0; trb ffffff800a4ea1c0
[ 4359.931691] tegra-xudc-new 700d0000.xudc: bytes transferred 34 / 34
[ 4359.931694] tegra-xudc-new 700d0000.xudc: completing request ffffffc0ed9f0b40 on ep 0 with status 0
[ 4359.931704] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea1d0, lo = 0x0, hi = 0x0, status = 0x0, control = 0x1024
[ 4359.931706] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x50000
[ 4359.931724] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821170, lo = 0xffe8e1d0, hi = 0x0, status = 0x1000000, control = 0x8001
[ 4359.931727] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea1d0 -> ffffff800a4ea1d0; trb ffffff800a4ea1d0
[ 4359.931730] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 4359.931734] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f7a9c0c0 on ep 0 with status 0
[ 4359.931767] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821180, lo = 0x3000680, hi = 0xff0000, status = 0x1000006, control = 0xfc01
[ 4359.931779] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea1e0, lo = 0xffd38000, hi = 0x0, status = 0x4, control = 0x10c24
[ 4359.931781] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x60000
[ 4359.931795] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821190, lo = 0xffe8e1e0, hi = 0x0, status = 0x1000000, control = 0x8001
[ 4359.931799] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea1e0 -> ffffff800a4ea1e0; trb ffffff800a4ea1e0
[ 4359.931803] tegra-xudc-new 700d0000.xudc: bytes transferred 4 / 4
[ 4359.931806] tegra-xudc-new 700d0000.xudc: completing request ffffffc0ed9f0b40 on ep 0 with status 0
[ 4359.931817] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea1f0, lo = 0x0, hi = 0x0, status = 0x0, control = 0x1024
[ 4359.931820] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x60000
[ 4359.931839] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8211a0, lo = 0xffe8e1f0, hi = 0x0, status = 0x1000000, control = 0x8001
[ 4359.931843] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea1f0 -> ffffff800a4ea1f0; trb ffffff800a4ea1f0
[ 4359.931846] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 4359.931850] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f7a9c0c0 on ep 0 with status 0
[ 4359.931878] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8211b0, lo = 0x3020680, hi = 0xff0409, status = 0x1000007, control = 0xfc01
[ 4359.931890] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea200, lo = 0xffd38000, hi = 0x0, status = 0x1e, control = 0x10c24
[ 4359.931892] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x70000
[ 4359.931906] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8211c0, lo = 0xffe8e200, hi = 0x0, status = 0x1000000, control = 0x8001
[ 4359.931910] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea200 -> ffffff800a4ea200; trb ffffff800a4ea200
[ 4359.931913] tegra-xudc-new 700d0000.xudc: bytes transferred 30 / 30
[ 4359.931916] tegra-xudc-new 700d0000.xudc: completing request ffffffc0ed9f0b40 on ep 0 with status 0
[ 4359.931927] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea210, lo = 0x0, hi = 0x0, status = 0x0, control = 0x1024
[ 4359.931930] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x70000
[ 4359.931949] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8211d0, lo = 0xffe8e210, hi = 0x0, status = 0x1000000, control = 0x8001
[ 4359.931953] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea210 -> ffffff800a4ea210; trb ffffff800a4ea210
[ 4359.931956] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 4359.931960] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f7a9c0c0 on ep 0 with status 0
[ 4359.932006] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8211e0, lo = 0x3010680, hi = 0xff0409, status = 0x1000008, control = 0xfc01
[ 4359.932017] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea220, lo = 0xffd38000, hi = 0x0, status = 0x24, control = 0x10c24
[ 4359.932020] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x80000
[ 4359.932033] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8211f0, lo = 0xffe8e220, hi = 0x0, status = 0x1000000, control = 0x8001
[ 4359.932037] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea220 -> ffffff800a4ea220; trb ffffff800a4ea220
[ 4359.932041] tegra-xudc-new 700d0000.xudc: bytes transferred 36 / 36
[ 4359.932044] tegra-xudc-new 700d0000.xudc: completing request ffffffc0ed9f0b40 on ep 0 with status 0
[ 4359.932054] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea230, lo = 0x0, hi = 0x0, status = 0x0, control = 0x1024
[ 4359.932056] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x80000
[ 4359.932077] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821200, lo = 0xffe8e230, hi = 0x0, status = 0x1000000, control = 0x8001
[ 4359.932081] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea230 -> ffffff800a4ea230; trb ffffff800a4ea230
[ 4359.932084] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 4359.932088] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f7a9c0c0 on ep 0 with status 0
[ 4359.932154] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821210, lo = 0x3030680, hi = 0xff0409, status = 0x1000009, control = 0xfc01
[ 4359.932166] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea240, lo = 0xffd38000, hi = 0x0, status = 0x22, control = 0x10c24
[ 4359.932169] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x90000
[ 4359.932184] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821220, lo = 0xffe8e240, hi = 0x0, status = 0x1000000, control = 0x8001
[ 4359.932188] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea240 -> ffffff800a4ea240; trb ffffff800a4ea240
[ 4359.932191] tegra-xudc-new 700d0000.xudc: bytes transferred 34 / 34
[ 4359.932195] tegra-xudc-new 700d0000.xudc: completing request ffffffc0ed9f0b40 on ep 0 with status 0
[ 4359.932205] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea250, lo = 0x0, hi = 0x0, status = 0x0, control = 0x1024
[ 4359.932208] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x90000
[ 4359.932222] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821230, lo = 0xffe8e250, hi = 0x0, status = 0x1000000, control = 0x8001
[ 4359.932226] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea250 -> ffffff800a4ea250; trb ffffff800a4ea250
[ 4359.932229] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 4359.932233] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f7a9c0c0 on ep 0 with status 0
[ 4359.932522] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821240, lo = 0x10900, hi = 0x0, status = 0x100000a, control = 0xfc01
[ 4359.932527] tegra-xudc-new 700d0000.xudc: USB_REQ_SET_CONFIGURATION
[ 4359.932533] configfs-gadget gadget: high-speed config #1: c
[ 4359.932559] tegra-xudc-new 700d0000.xudc: ep 3 (type: 3, dir: in) enabled
[ 4359.932571] tegra-xudc-new 700d0000.xudc: tegra_xudc_set_selfpowered: 0
[ 4359.932576] tegra-xudc-new 700d0000.xudc: tegra_xudc_gadget_vbus_draw: 500 mA
[ 4359.932584] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea260, lo = 0x0, hi = 0x0, status = 0x0, control = 0x11024
[ 4359.932589] tegra-xudc-new 700d0000.xudc: ring doorbell: 0xa0000
[ 4359.932603] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821250, lo = 0xffe8e260, hi = 0x0, status = 0x1000000, control = 0x8001
[ 4359.932608] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea260 -> ffffff800a4ea260; trb ffffff800a4ea260
[ 4359.932613] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 4359.932618] tegra-xudc-new 700d0000.xudc: completing request ffffffc0ed9f0b40 on ep 0 with status 0
[ 4359.932642] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821260, lo = 0x3040680, hi = 0xff0409, status = 0x100000b, control = 0xfc01
[ 4359.932659] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea270, lo = 0xffd38000, hi = 0x0, status = 0x28, control = 0x10c24
[ 4359.932664] tegra-xudc-new 700d0000.xudc: ring doorbell: 0xb0000
[ 4359.932689] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821270, lo = 0xffe8e270, hi = 0x0, status = 0x1000000, control = 0x8001
[ 4359.932694] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea270 -> ffffff800a4ea270; trb ffffff800a4ea270
[ 4359.932697] tegra-xudc-new 700d0000.xudc: bytes transferred 40 / 40
[ 4359.932701] tegra-xudc-new 700d0000.xudc: completing request ffffffc0ed9f0b40 on ep 0 with status 0
[ 4359.932712] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea280, lo = 0x0, hi = 0x0, status = 0x0, control = 0x1024
[ 4359.932714] tegra-xudc-new 700d0000.xudc: ring doorbell: 0xb0000
[ 4359.932731] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821280, lo = 0xffe8e280, hi = 0x0, status = 0x1000000, control = 0x8001
[ 4359.932735] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea280 -> ffffff800a4ea280; trb ffffff800a4ea280
[ 4359.932738] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 4359.932741] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f7a9c0c0 on ep 0 with status 0
[ 4359.932865] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821290, lo = 0x3030680, hi = 0xff0409, status = 0x100000c, control = 0xfc01
[ 4359.932878] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea290, lo = 0xffd38000, hi = 0x0, status = 0x22, control = 0x10c24
[ 4359.932881] tegra-xudc-new 700d0000.xudc: ring doorbell: 0xc0000
[ 4359.932901] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8212a0, lo = 0xffe8e290, hi = 0x0, status = 0x1000000, control = 0x8001
[ 4359.932906] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea290 -> ffffff800a4ea290; trb ffffff800a4ea290
[ 4359.932911] tegra-xudc-new 700d0000.xudc: bytes transferred 34 / 34
[ 4359.932917] tegra-xudc-new 700d0000.xudc: completing request ffffffc0ed9f0b40 on ep 0 with status 0
[ 4359.932928] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea2a0, lo = 0x0, hi = 0x0, status = 0x0, control = 0x1024
[ 4359.932933] tegra-xudc-new 700d0000.xudc: ring doorbell: 0xc0000
[ 4359.932947] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8212b0, lo = 0xffe8e2a0, hi = 0x0, status = 0x1000000, control = 0x8001
[ 4359.932952] tegra-xudc-new 700d0000.xudc: trb_in_request: request ffffff800a4ea2a0 -> ffffff800a4ea2a0; trb ffffff800a4ea2a0
[ 4359.932957] tegra-xudc-new 700d0000.xudc: bytes transferred 0 / 0
[ 4359.932963] tegra-xudc-new 700d0000.xudc: completing request ffffffc0f7a9c0c0 on ep 0 with status 0
[ 4359.933053] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8212c0, lo = 0xa21, hi = 0x0, status = 0x100000d, control = 0xfc01
[ 4359.933116] tegra-xudc-new 700d0000.xudc: TRANSFER: ffffff800a4ea800, lo = 0xffd37d00, hi = 0x0, status = 0x3, control = 0x421
[ 4359.933124] tegra-xudc-new 700d0000.xudc: ring doorbell: 0x300
[ 4359.933645] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8212d0, lo = 0x22000681, hi = 0x320000, status = 0x100000e, control = 0xfc01
[ 4359.933780] android_work: sent uevent USB_STATE=CONFIGURED
[ 4365.375132] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8212e0, lo = 0x22000681, hi = 0x320000, status = 0x100000f, control = 0xfc01
[ 4370.495117] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a8212f0, lo = 0x22000681, hi = 0x320000, status = 0x1000010, control = 0xfc01
[ 4375.614836] tegra-xudc-new 700d0000.xudc: EVENT: ffffff800a821300, lo = 0x22000681, hi = 0x320000, status = 0x1000011, control = 0xfc01
KiwiLostInMelb commented 2 years ago

2 files attached to diff compare. I see a difference after USB_STATE=CONNECTED WIN: bytes transferred 18 / 18 Linux: bytes transferred 9 / 9

linux_kern.txt win_kernel.txt

vpelletier commented 2 years ago

To my untrained eye, it looks promising that there are consecutive EVENT lines at the end in the linux traces: this suggests to me that the driver is getting notified by the hardware of something happening. This would push the probability of the bug location away from the silicon and into the software side, which would increase the probability of a fix happening (and less headache for you: no board change/swaps).

But again, I have zero experience with this hardware and only a tiny bit of experience poking at the kernel source, so I can be way off.

KiwiLostInMelb commented 2 years ago

I suspect the answer will be to just wait for the 5.? kernel later this year (maybe).

There are a lot of changes for tegra in the 5 base looking through the history. https://github.com/torvalds/linux/commits/master/drivers/usb/gadget/udc/tegra-xudc.c https://github.com/torvalds/linux/commits/master/drivers/phy/tegra

So given that Nvidia are likely to never respond to this one directly I will program a micro to handle the usb host side and just send the reports via TTL serial on the Jetson at max speed. Hopefully they fix it sometime soon and I can then just remove the extra hardware and re-enable your code. I have a few esp32 and older PIC18F micros hanging around that support USB device mode and there are lots of samples for usb mouse to copy.

EDIT: Just checked - esp32 is ls only so I also have a spare stm32 that supports hs usb device.

This is a prototype so we haven't spent much $ other than time and less hair. End result will be probably Jetson NX or TX -much faster gpu with the same cpu. For a POC the Nano fit the budget.

Thank you once again for all your extended time and effort. Really appreciate the help a lot and also the advice on how to go about getting it fixed.

I have closed the issue with my thanks!!!