Hi,
I'm having trouble getting the USB MSD example working on the nRF52840. I have attached the terminal output from the example with debug level logging enabled for both USB and MSD.
As far as I can see there seems to be some issue with the MSD part as USB enumaration seems to work on both Windows and Linux. But on both the example seems to get stuck just after the host sends MSC_REQUEST_GET_MAX_LUN. I think the next log line after that means that the example does send a reponse back but for some reason this is where it fails. After that it just waits for about 20s and then the host sends a USB reset. I tried this on both Windows 10 and also Linux on completely different physical machines with different USB cables. I''m running the example on a nRF52840-Preview-DK (compiled for nrf52840dk_nrf840 in VSCode).
I have tried compiling for different memory and filesystem configurations but that doesn't seem to have any effect on this issue.
I have tried the USB CDC example on the same board and that seems to work well.
Can you advise what else I should try. I can't find anyone else having a similar issue so I'm a bit stuck.
Here is what dmesg on Ubuntu shows for this:
[99610.787545] usb 1-6.2: new full-speed USB device number 38 using xhci_hcd
[99610.890092] usb 1-6.2: New USB device found, idVendor=2fe3, idProduct=0008, bcdDevice= 3.02
[99610.890098] usb 1-6.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[99610.890100] usb 1-6.2: Product: Zephyr MSC sample
[99610.890102] usb 1-6.2: Manufacturer: ZEPHYR
[99610.890103] usb 1-6.2: SerialNumber: CD561E4B0B6207A7
[99610.895885] usb-storage 1-6.2:1.0: USB Mass Storage device detected
[99610.896036] scsi host7: usb-storage 1-6.2:1.0
[99642.779806] usb 1-6.2: reset full-speed USB device number 38 using xhci_hcd
[99654.309563] usb 1-6.2: USB disconnect, device number 38
[99812.850577] usb 1-14: reset high-speed USB device number 6 using xhci_hcd
*** Booting Zephyr OS build v3.2.99-ncs1 *** Area 0 at 0x0 on mx25r6435f@0 for 131072 bytes [00:00:00.249,816] <dbg> usb_descriptor: ascii7_to_utf16le: char 7 : 37, idx 15 -> 31 [00:00:00.249,847] <dbg> usb_descriptor: ascii7_to_utf16le: char A : 41, idx 14 -> 29 --- 41 messages dropped --- [00:00:00.249,877] <dbg> usb_descriptor: ascii7_to_utf16le: char 7 : 37, idx 13 -> 27 [00:00:00.249,877] <dbg> usb_descriptor: ascii7_to_utf16le: char 0 : 30, idx 12 -> 25 [00:00:00.249,908] <dbg> usb_descriptor: ascii7_to_utf16le: char 2 : 32, idx 11 -> 23 [00:00:00.249,908] <dbg> usb_deMount /NAND:: 0 sc/NAND:: bsize = 512 ; frsize = 512 ; blocks = 216 ; bfree = 216 /NAND: opendir: 0 riEnd of files ptor: ascii7_to_utf16le: char 6 : 36, idx 10 -> 21 [00:00:00.249,938] <dbg> usb_descriptor: ascii7_to_utf16le: char B : 42, idx 9 -> 19 [00:00:00.249,969] <dbg> usb_descriptor: ascii7_to_utf16le: char 0 : 30, idx 8 -> 17 [00:00:00.249,969] <dbg> usb_descriptor: ascii7_to_utf16le: char B : 42, idx 7 -> 15 [00:00:00.250,000] <dbg> usb_descriptor: ascii7_to_utf16le: char 4 : 34, idx 6 -> 13 [00:00:00.250,030] <dbg> usb_descriptor: ascii7_to_utf16le: char E : 45, idx 5 -> 11 [00:00:00.250,030] <dbg> usb_descriptor: ascii7_to_utf16le: char 1 : 31, idx 4 -> 9 [00:00:00.250,061] <dbg> usb_descriptor: ascii7_to_utf16le: char 6 : 36, idx 3 -> 7 [00:00:00.250,061] <dbg> usb_descriptor: ascii7_to_utf16le: char 5 : 35, idx 2 -> 5 [00:00:00.250,091] <dbg> usb_descriptor: ascii7_to_utf16le: char D : 44, idx 1 -> 3 [00:00:00.250,122] <dbg> usb_descriptor: ascii7_to_utf16le: char C : 43, idx 0 -> 1 [00:00:00.254,150] <inf> flashdisk: Initialize device NAND [00:00:00.254,150] <inf> flashdisk: offset 0, sector size 512, page size 4096, volume size 131072 [00:00:00.254,211] <inf> usb_msc: Sect Count 256 [00:00:00.254,211] <inf> usb_msc: Memory Size 131072 [00:00:00.254,333] <inf> main: Test [00:00:00.258,514] <inf> flashdisk: Initialize device NAND [00:00:00.258,544] <inf> flashdisk: offset 0, sector size 512, page size 4096, volume size 131072 [00:00:00.319,763] <dbg> usb_device: usb_enable: lock usb_enable_lock mutex [00:00:00.319,854] <dbg> usb_device: composite_setup_ep_cb: set cb, ep: 0x1 [00:00:00.319,854] <dbg> usb_device: composite_setup_ep_cb: set cb, ep: 0x81 [00:00:00.319,885] <dbg> usb_device: usb_enable: unlock usb_enable_lock mutex [00:00:00.319,885] <inf> main: The device is put in USB mass storage mode. [00:00:14.732,238] <dbg> usb_msc: mass_storage_status_cb: USB device connected [00:00:14.732,238] <inf> main: USB Connected [00:00:14.735,351] <dbg> usb_msc: mass_storage_status_cb: USB device suspended [00:00:14.735,351] <inf> main: USB Suspended [00:00:14.853,881] <dbg> usb_msc: mass_storage_status_cb: USB device reset detected [00:00:14.853,973] <inf> main: USB Reset [00:00:14.853,973] <dbg> usb_msc: mass_storage_status_cb: USB device resumed [00:00:14.854,003] <inf> main: USB Resumed [00:00:14.941,864] <dbg> usb_device: usb_handle_control_transfer: ep 0x00, status 0x00 [00:00:14.941,894] <dbg> usb_device: custom_handler: bRequest 0x06, wIndex 0x0000 [00:00:14.941,925] <dbg> usb_device: usb_get_descriptor: Get Descriptor request [00:00:14.942,016] <dbg> usb_device: usb_handle_control_transfer: ep 0x80, status 0x02 [00:00:14.942,169] <dbg> usb_msc: mass_storage_status_cb: USB device reset detected [00:00:14.942,230] <inf> main: USB Reset [00:00:15.040,832] <dbg> usb_device: usb_handle_control_transfer: ep 0x00, status 0x00 --- 1 messages dropped --- [00:00:15.040,863] <dbg> usb_device: usb_get_descriptor: Get Descriptor request [00:00:15.041,015] <dbg> usb_device: usb_handle_control_transfer: ep 0x80, status 0x02 [00:00:15.047,668] <dbg> usb_device: usb_handle_control_transfer: ep 0x00, status 0x00 [00:00:15.047,698] <dbg> usb_device: custom_handler: bRequest 0x06, wIndex 0x0000 [00:00:15.047,698] <dbg> usb_device: usb_get_descriptor: Get Descriptor request [00:00:15.047,851] <dbg> usb_device: usb_handle_control_transfer: ep 0x80, status 0x02 [00:00:15.047,943] <dbg> usb_device: usb_handle_control_transfer: ep 0x00, status 0x00 [00:00:15.047,973] <dbg> usb_device: custom_handler: bRequest 0x06, wIndex 0x0409 [00:00:15.047,973] <dbg> usb_device: usb_get_descriptor: Get Descriptor request [00:00:15.048,126] <dbg> usb_device: usb_handle_control_transfer: ep 0x80, status 0x02 [00:00:15.048,217] <dbg> usb_device: usb_handle_control_transfer: ep 0x00, status 0x00 [00:00:15.048,248] <dbg> usb_device: custom_handler: bRequest 0x06, wIndex 0x0000 [00:00:15.048,248] <dbg> usb_device: usb_get_descriptor: Get Descriptor request [00:00:15.048,339] <dbg> usb_device: usb_handle_control_transfer: ep 0x80, status 0x02 [00:00:15.048,431] <dbg> usb_device: usb_handle_control_transfer: ep 0x00, status 0x00 --- 14 messages dropped --- [00:00:15.201,385] <dbg> usb_device: custom_handler: bRequest 0x06, wIndex 0x0000 --- 9 messages dropped --- [00:00:15.201,385] <dbg> usb_device: usb_get_descriptor: Get Descriptor request [00:00:15.201,507] <dbg> usb_device: usb_handle_control_transfer: ep 0x80, status 0x02 [00:00:15.201,599] <dbg> usb_device: usb_handle_control_transfer: ep 0x00, status 0x00 [00:00:15.201,629] <dbg> usb_device: custom_handler: bRequest 0x06, wIndex 0x0000 [00:00:15.201,660] <dbg> usb_device: usb_get_descriptor: Get Descriptor request [00:00:15.201,721] <dbg> usb_device: usb_handle_control_transfer: ep 0x80, status 0x02 [00:00:15.201,843] <dbg> usb_device: usb_handle_control_transfer: ep 0x00, status 0x00 [00:00:15.201,873] <dbg> usb_device: custom_handler: bRequest 0x06, wIndex 0x0409 [00:00:15.201,873] <dbg> usb_device: usb_get_descriptor: Get Descriptor request [00:00:15.201,995] <dbg> usb_device: usb_handle_control_transfer: ep 0x80, status 0x02 [00:00:15.202,087] <dbg> usb_device: usb_handle_control_transfer: ep 0x00, status 0x00 [00:00:15.202,117] <dbg> usb_device: custom_handler: bRequest 0x06, wIndex 0x0409 [00:00:15.202,148] <dbg> usb_device: usb_get_descriptor: Get Descriptor request [00:00:15.202,270] <dbg> usb_device: usb_handle_control_transfer: ep 0x80, status 0x02 [00:00:15.204,650] <dbg> usb_device: usb_handle_control_transfer: ep 0x00, status 0x00 [00:00:15.204,681] <dbg> usb_device: custom_handler: bRequest 0x09, wIndex 0x0000 [00:00:15.204,711] <dbg> usb_device: usb_set_configuration: Set Configuration 1 request [00:00:15.204,742] <dbg> usb_device: set_endpoint: Set endpoint 0x81 type 2 MPS 64 [00:00:15.204,742] <dbg> usb_device: set_endpoint: Set endpoint 0x1 type 2 MPS 64 [00:00:15.204,803] <dbg> usb_msc: mass_storage_status_cb: USB device configured [00:00:15.204,803] <inf> main: USB Configured [00:00:15.205,535] <dbg> usb_device: usb_handle_control_transfer: ep 0x00, status 0x00 [00:00:15.205,566] <dbg> usb_device: class_handler: bRequest 0xfe, wIndex 0x0000 [00:00:15.205,566] <dbg> usb_msc: mass_storage_class_handle_req: MSC_REQUEST_GET_MAX_LUN [00:00:15.205,657] <dbg> usb_device: usb_handle_control_transfer: ep 0x80, status 0x02 [00:00:35.219,512] <dbg> usb_msc: mass_storage_status_cb: USB device reset detected [00:00:35.219,604] <inf> main: USB Reset [00:00:35.307,342] <dbg> usb_device: usb_handle_control_transfer: ep 0x00, status 0x00 [00:00:35.307,373] <dbg> usb_device: custom_handler: bRequest 0x06, wIndex 0x0000 [00:00:35.307,403] <dbg> usb_device: usb_get_descriptor: Get Descriptor request [00:00:35.307,525] <dbg> usb_device: usb_handle_control_transfer: ep 0x80, status 0x02 [00:00:35.307,586] <dbg> usb_msc: mass_storage_status_cb: USB device reset detected [00:00:35.307,647] <inf> main: USB Reset [00:00:35.406,311] <dbg> usb_device: usb_handle_control_transfer: ep 0x00, status 0x00 [00:00:35.406,341] <dbg> usb_device: custom_handler: bRequest 0x06, wIndex 0x0000 [00:00:35.406,341] <dbg> usb_device: usb_get_descriptor: Get Descriptor request [00:00:35.406,494] <dbg> usb_device: usb_handle_control_transfer: ep 0x80, status 0x02 [00:00:35.406,555] <dbg> usb_device: usb_handle_control_transfer: ep 0x00, status 0x00 [00:00:35.406,585] <dbg> usb_device: custom_handler: bRequest 0x09, wIndex 0x0000 [00:00:35.406,616] <dbg> usb_device: usb_set_configuration: Set Configuration 1 request [00:00:35.406,616] <dbg> usb_device: set_endpoint: Set endpoint 0x81 type 2 MPS 64 [00:00:35.406,646] <dbg> usb_device: set_endpoint: Set endpoint 0x1 type 2 MPS 64 [00:00:35.406,677] <dbg> usb_msc: mass_storage_status_cb: USB device configured [00:00:35.406,677] <inf> main: USB Configured