STM32F429I-DISC1 USB mass storage demo not working

[smfelsher]

Describe the bug

I am running the USB mass storage demo on my board: stm32f429i_disc1. I see three (3) different types of behavior.

1. Device enumerates with no warnings.
2. Device enumerates, but reports several warnings and resets several times before enumerating.
3. Does not enumerate.

I am using my development machine, Arch Linux, as the host device.

I performed a git bisect and found that this commit, 375e8e6ccb287707586ebb1fc58ab1c90c11b369, eventually enumerates, but with many warnings and resets.

Commit 7ec83e5c952, which is a later commit, appears to fix it. My device enumerates with no warnings.

However, the current on main, 86a46c48bee, does not enumerate the device at all.

Regression

• This is a regression.

Steps to reproduce

1. cd zephyr/samples/subsys/usb/mass
2. west build -b stm32f429i_disc1 . -- -DEXTRA_DTC_OVERLAY_FILE="ramdisk.overlay" -DCONFIG_APP_MSC_STORAGE_RAM=y
3. west flash

Relevant log output

# A clean enumeration
## Logs from my host (dmesg)
523854.022734] usb 1-5.1: new full-speed USB device number 32 using xhci_hcd
[523854.098633] usb 1-5.1: New USB device found, idVendor=2fe3, idProduct=0008, bcdDevice= 4.02
[523854.098637] usb 1-5.1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[523854.098639] usb 1-5.1: Product: USBD MSC sample
[523854.098640] usb 1-5.1: Manufacturer: Zephyr Project
[523854.098641] usb 1-5.1: SerialNumber: 363937393133510600450026
[523854.104265] usb-storage 1-5.1:1.0: USB Mass Storage device detected
[523854.104486] scsi host7: usb-storage 1-5.1:1.0
[523855.137452] scsi 7:0:0:0: Direct-Access     Zephyr   RAMDisk          0.00 PQ: 0 ANSI: 4
[523855.138766] sd 7:0:0:0: [sdd] 192 512-byte logical blocks: (98.3 kB/96.0 KiB)
[523855.139441] sd 7:0:0:0: [sdd] Write Protect is off
[523855.139443] sd 7:0:0:0: [sdd] Mode Sense: 03 00 00 00
[523855.139960] sd 7:0:0:0: [sdd] No Caching mode page found
[523855.139962] sd 7:0:0:0: [sdd] Assuming drive cache: write through
[523855.171476]  sdd:
[523855.171498] sd 7:0:0:0: [sdd] Attached SCSI removable disk

## Logs from the device console
*** Booting Zephyr OS build v4.2.0-4729-g7ec83e5c9525 ***
Mount /RAM:: 0
/RAM:: bsize = 512 ; frsize = 512 ; blocks = 158 ; bfree = 158
/RAM: opendir: 0
End of files
[00:00:00.061,000] <inf> main: The device is put in USB mass storage mode
[00:00:00.480,000] <wrn> udc: Spurious resume event
[00:00:00.550,000] <inf> usbd_msc: Enable
[00:00:00.550,000] <inf> usbd_msc: Bulk-Only Mass Storage Reset

# Success with a lot of resets
## Host (dmesg)
[523978.437859] usb 1-5.1: new full-speed USB device number 33 using xhci_hcd
[523978.513617] usb 1-5.1: New USB device found, idVendor=2fe3, idProduct=0008, bcdDevice= 4.02
[523978.513621] usb 1-5.1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[523978.513622] usb 1-5.1: Product: USBD MSC sample
[523978.513623] usb 1-5.1: Manufacturer: Zephyr Project
[523978.513624] usb 1-5.1: SerialNumber: 363937393133510600450026
[523978.519082] usb-storage 1-5.1:1.0: USB Mass Storage device detected
[523978.519342] scsi host7: usb-storage 1-5.1:1.0
[523979.556599] scsi 7:0:0:0: Direct-Access     Zephyr   RAMDisk          0.00 PQ: 0 ANSI: 4
[523979.558513] sd 7:0:0:0: [sdd] 192 512-byte logical blocks: (98.3 kB/96.0 KiB)
[523979.623131] usb 1-5.1: reset full-speed USB device number 33 using xhci_hcd
[523979.786129] usb 1-5.1: reset full-speed USB device number 33 using xhci_hcd
[523979.940018] usb 1-5.1: reset full-speed USB device number 33 using xhci_hcd
[523980.092119] usb 1-5.1: reset full-speed USB device number 33 using xhci_hcd
[523980.243092] usb 1-5.1: reset full-speed USB device number 33 using xhci_hcd
[523980.408192] usb 1-5.1: reset full-speed USB device number 33 using xhci_hcd
[523980.487566] sd 7:0:0:0: [sdd] Write Protect is off
[523980.487569] sd 7:0:0:0: [sdd] Mode Sense: 03 00 00 00
[523980.550001] usb 1-5.1: reset full-speed USB device number 33 using xhci_hcd
[523980.701026] usb 1-5.1: reset full-speed USB device number 33 using xhci_hcd
[523980.860997] usb 1-5.1: reset full-speed USB device number 33 using xhci_hcd
[523981.013104] usb 1-5.1: reset full-speed USB device number 33 using xhci_hcd
[523981.168197] usb 1-5.1: reset full-speed USB device number 33 using xhci_hcd
[523981.332096] usb 1-5.1: reset full-speed USB device number 33 using xhci_hcd
[523981.412356] sd 7:0:0:0: [sdd] No Caching mode page found
[523981.412359] sd 7:0:0:0: [sdd] Assuming drive cache: write through
[523981.493166] usb 1-5.1: reset full-speed USB device number 33 using xhci_hcd
[523981.646108] usb 1-5.1: reset full-speed USB device number 33 using xhci_hcd
[523981.808222] usb 1-5.1: reset full-speed USB device number 33 using xhci_hcd
[523981.973225] usb 1-5.1: reset full-speed USB device number 33 using xhci_hcd
[523982.128189] usb 1-5.1: reset full-speed USB device number 33 using xhci_hcd
[523982.279176] usb 1-5.1: reset full-speed USB device number 33 using xhci_hcd
[523982.433217] usb 1-5.1: reset full-speed USB device number 33 using xhci_hcd
[523982.585093] usb 1-5.1: reset full-speed USB device number 33 using xhci_hcd
[523982.748132] usb 1-5.1: reset full-speed USB device number 33 using xhci_hcd
[523982.911137] usb 1-5.1: reset full-speed USB device number 33 using xhci_hcd
[523983.065246] usb 1-5.1: reset full-speed USB device number 33 using xhci_hcd
[523983.216253] usb 1-5.1: reset full-speed USB device number 33 using xhci_hcd
[523983.313736]  sdd:
[523983.313756] sd 7:0:0:0: [sdd] Attached SCSI removable disk

## Device console
*** Booting Zephyr OS build v4.2.0-1270-g375e8e6ccb28 ***
Mount /RAM:: 0
/RAM:: bsize = 512 ; frsize = 512 ; blocks = 158 ; bfree = 158
/RAM: opendir: 0
End of files
[00:00:00.061,000] <inf> main: The device is put in USB mass storage mode
[00:00:00.455,000] <inf> usbd_msc: Enable
[00:00:00.455,000] <inf> usbd_msc: Bulk-Only Mass Storage Reset
[00:00:01.506,000] <inf> usbd_msc: Disable
[00:00:01.506,000] <wrn> usbd_msc: request ep 0x01, len 0 cancelled
[00:00:01.645,000] <inf> usbd_msc: Enable
[00:00:01.645,000] <inf> usbd_msc: Bulk-Only Mass Storage Reset
[00:00:01.670,000] <inf> usbd_msc: Disable
[00:00:01.670,000] <wrn> usbd_msc: request ep 0x01, len 0 cancelled
[00:00:01.799,000] <inf> usbd_msc: Enable
[00:00:01.799,000] <inf> usbd_msc: Bulk-Only Mass Storage Reset
[00:00:01.824,000] <inf> usbd_msc: Disable
[00:00:01.824,000] <wrn> usbd_msc: request ep 0x01, len 0 cancelled
[00:00:01.951,000] <inf> usbd_msc: Enable
[00:00:01.951,000] <inf> usbd_msc: Bulk-Only Mass Storage Reset
[00:00:01.976,000] <inf> usbd_msc: Disable
[00:00:01.976,000] <wrn> usbd_msc: request ep 0x01, len 0 cancelled
[00:00:02.103,000] <inf> usbd_msc: Enable
[00:00:02.103,000] <inf> usbd_msc: Bulk-Only Mass Storage Reset
[00:00:02.128,000] <inf> usbd_msc: Disable
[00:00:02.128,000] <wrn> usbd_msc: request ep 0x01, len 0 cancelled
[00:00:02.265,000] <inf> usbd_msc: Enable
[00:00:02.265,000] <inf> usbd_msc: Bulk-Only Mass Storage Reset
[00:00:02.292,000] <inf> usbd_msc: Disable
[00:00:02.292,000] <wrn> usbd_msc: request ep 0x01, len 0 cancelled
[00:00:02.419,000] <inf> usbd_msc: Enable
[00:00:02.419,000] <inf> usbd_msc: Bulk-Only Mass Storage Reset
[00:00:02.435,000] <inf> usbd_msc: Disable
[00:00:02.435,000] <wrn> usbd_msc: request ep 0x01, len 0 cancelled
[00:00:02.560,000] <inf> usbd_msc: Enable
[00:00:02.560,000] <inf> usbd_msc: Bulk-Only Mass Storage Reset
[00:00:02.585,000] <inf> usbd_msc: Disable
[00:00:02.585,000] <wrn> usbd_msc: request ep 0x01, len 0 cancelled
[00:00:02.712,000] <inf> usbd_msc: Enable
[00:00:02.712,000] <inf> usbd_msc: Bulk-Only Mass Storage Reset
[00:00:02.736,000] <inf> usbd_msc: Disable
[00:00:02.736,000] <wrn> usbd_msc: request ep 0x01, len 0 cancelled
[00:00:02.872,000] <inf> usbd_msc: Enable
[00:00:02.872,000] <inf> usbd_msc: Bulk-Only Mass Storage Reset
[00:00:02.897,000] <inf> usbd_msc: Disable
[00:00:02.897,000] <wrn> usbd_msc: request ep 0x01, len 0 cancelled
[00:00:03.025,000] <inf> usbd_msc: Enable
[00:00:03.025,000] <inf> usbd_msc: Bulk-Only Mass Storage Reset
[00:00:03.051,000] <inf> usbd_msc: Disable
[00:00:03.051,000] <wrn> usbd_msc: request ep 0x01, len 0 cancelled
[00:00:03.190,000] <inf> usbd_msc: Enable
[00:00:03.190,000] <inf> usbd_msc: Bulk-Only Mass Storage Reset
[00:00:03.215,000] <inf> usbd_msc: Disable
[00:00:03.215,000] <wrn> usbd_msc: request ep 0x01, len 0 cancelled
[00:00:03.343,000] <inf> usbd_msc: Enable
[00:00:03.343,000] <inf> usbd_msc: Bulk-Only Mass Storage Reset
[00:00:03.367,000] <inf> usbd_msc: Disable
[00:00:03.367,000] <wrn> usbd_msc: request ep 0x01, len 0 cancelled
[00:00:03.505,000] <inf> usbd_msc: Enable
[00:00:03.505,000] <inf> usbd_msc: Bulk-Only Mass Storage Reset
[00:00:03.530,000] <inf> usbd_msc: Disable
[00:00:03.530,000] <wrn> usbd_msc: request ep 0x01, len 0 cancelled
[00:00:03.668,000] <inf> usbd_msc: Enable
[00:00:03.668,000] <inf> usbd_msc: Bulk-Only Mass Storage Reset
[00:00:03.693,000] <inf> usbd_msc: Disable
[00:00:03.693,000] <wrn> usbd_msc: request ep 0x01, len 0 cancelled
[00:00:03.830,000] <inf> usbd_msc: Enable
[00:00:03.830,000] <inf> usbd_msc: Bulk-Only Mass Storage Reset
[00:00:03.856,000] <inf> usbd_msc: Disable
[00:00:03.856,000] <wrn> usbd_msc: request ep 0x01, len 0 cancelled
[00:00:03.986,000] <inf> usbd_msc: Enable
[00:00:03.986,000] <inf> usbd_msc: Bulk-Only Mass Storage Reset
[00:00:04.011,000] <inf> usbd_msc: Disable
[00:00:04.011,000] <wrn> usbd_msc: request ep 0x01, len 0 cancelled
[00:00:04.139,000] <inf> usbd_msc: Enable
[00:00:04.139,000] <inf> usbd_msc: Bulk-Only Mass Storage Reset
[00:00:04.164,000] <inf> usbd_msc: Disable
[00:00:04.164,000] <wrn> usbd_msc: request ep 0x01, len 0 cancelled
[00:00:04.301,000] <inf> usbd_msc: Enable
[00:00:04.301,000] <inf> usbd_msc: Bulk-Only Mass Storage Reset
[00:00:04.318,000] <inf> usbd_msc: Disable
[00:00:04.318,000] <wrn> usbd_msc: request ep 0x01, len 0 cancelled
[00:00:04.444,000] <inf> usbd_msc: Enable
[00:00:04.444,000] <inf> usbd_msc: Bulk-Only Mass Storage Reset
[00:00:04.469,000] <inf> usbd_msc: Disable
[00:00:04.469,000] <wrn> usbd_msc: request ep 0x01, len 0 cancelled
[00:00:04.607,000] <inf> usbd_msc: Enable
[00:00:04.607,000] <inf> usbd_msc: Bulk-Only Mass Storage Reset
[00:00:04.632,000] <inf> usbd_msc: Disable
[00:00:04.632,000] <wrn> usbd_msc: request ep 0x01, len 0 cancelled
[00:00:04.770,000] <inf> usbd_msc: Enable
[00:00:04.770,000] <inf> usbd_msc: Bulk-Only Mass Storage Reset
[00:00:04.795,000] <inf> usbd_msc: Disable
[00:00:04.795,000] <wrn> usbd_msc: request ep 0x01, len 0 cancelled
[00:00:04.923,000] <inf> usbd_msc: Enable
[00:00:04.923,000] <inf> usbd_msc: Bulk-Only Mass Storage Reset
[00:00:04.948,000] <inf> usbd_msc: Disable
[00:00:04.948,000] <wrn> usbd_msc: request ep 0x01, len 0 cancelled
[00:00:05.076,000] <inf> usbd_msc: Enable
[00:00:05.076,000] <inf> usbd_msc: Bulk-Only Mass Storage Reset
[00:00:05.101,000] <inf> usbd_msc: Disable
[00:00:05.101,000] <wrn> usbd_msc: request ep 0x01, len 0 cancelled
[00:00:05.227,000] <inf> usbd_msc: Enable
[00:00:05.227,000] <inf> usbd_msc: Bulk-Only Mass Storage Reset

# Failure to enumerate
## Host (dmesg)
[524111.825185] usb 1-5.1: new full-speed USB device number 34 using xhci_hcd
[524111.889099] usb 1-5.1: device descriptor read/64, error -32
[524112.064136] usb 1-5.1: device descriptor read/64, error -32
[524112.241110] usb 1-5.1: new full-speed USB device number 35 using xhci_hcd
[524112.304222] usb 1-5.1: device descriptor read/64, error -32
[524112.480221] usb 1-5.1: device descriptor read/64, error -32
[524112.583500] usb 1-5-port1: attempt power cycle
[524113.170147] usb 1-5.1: new full-speed USB device number 36 using xhci_hcd
[524113.170310] usb 1-5.1: Device not responding to setup address.
[524113.375331] usb 1-5.1: Device not responding to setup address.
[524113.583139] usb 1-5.1: device not accepting address 36, error -71
[524113.583615] usb 1-5.1: WARN: invalid context state for evaluate context command.
[524113.657145] usb 1-5.1: new full-speed USB device number 37 using xhci_hcd
[524113.657284] usb 1-5.1: Device not responding to setup address.
[524113.863348] usb 1-5.1: Device not responding to setup address.
[524114.071260] usb 1-5.1: device not accepting address 37, error -71
[524114.071622] usb 1-5.1: WARN: invalid context state for evaluate context command.
[524114.071683] usb 1-5-port1: unable to enumerate USB device

## Device console
*** Booting Zephyr OS build v4.2.0-6017-g86a46c48bee5 ***
Mount /RAM:: 0
/RAM:: bsize = 512 ; frsize = 512 ; blocks = 158 ; bfree = 158
/RAM: opendir: 0
End of files
[00:00:00.061,000] <inf> main: The device is put in USB mass storage mode

Impact

Showstopper – Prevents release or major functionality; system unusable.

Environment

• OS: Arch Linux
• Toolchain: SDK 0.17.4

Additional Context

No response

[mathieuchopstm]

Commit e31ddec seems to cause the issue. I'll investigate more...

[mathieuchopstm]

The problem is pretty obvious: during refactor, I removed a seemingly useless

zephyr/drivers/usb/udc/udc_stm32.c

Line 1212 in 7ec83e5

LL_AHB1_GRP1_DisableClockLowPower(LL_AHB1_GRP1_PERIPH_OTGHSULPI);

But the Reference Manual for most of the F4 series (all but STM32F446xx/STM32F469xx/STM32F479xx) states that:

RCC_AHB1LPENR:
    Bit 30 OTGHSULPILPEN:
        USB OTG HS ULPI clock enable during Sleep mode

        This bit is set and cleared by software.
        It must be cleared when the OTG_HS is used in FS mode.

The following patch fixes the issue on my side:

zephyr/drivers/usb/udc/udc_stm32.c

Lines 1283 to 1285 in fa61e87

	if (UDC_STM32_NODE_PHY_ITFACE(DT_DRV_INST(0)) == PCD_PHY_ULPI) {
	LL_AHB1_GRP1_EnableClock(LL_AHB1_GRP1_PERIPH_OTGHSULPI);
	}

	if (UDC_STM32_NODE_PHY_ITFACE(DT_DRV_INST(0)) == PCD_PHY_ULPI) { 
		LL_AHB1_GRP1_EnableClock(LL_AHB1_GRP1_PERIPH_OTGHSULPI); 
-	}
+	} else if (UDC_STM32_NODE_SPEED(DT_DRV_INST(0)) == PCD_SPEED_HIGH_IN_FULL) {
+		/*
+		 * Some parts of the STM32F4 series require the OTGHSULPILPEN to be
+		 * cleared if the OTG_HS is used in FS mode. Disable it on all parts
+		 * since it has no nefarious effect if performed when not required.
+		 */
+		LL_AHB1_GRP1_DisableClockLowPower(LL_AHB1_GRP1_PERIPH_OTGHSULPI);
+	}

[mathieuchopstm]

#97789 fixes issue on my side - @smfelsher please confirm on the PR thread that the issue is fixed on your side too.

I have added STM32F429I-DISC1 to my USB test roster to hopefully avoid such issues in the future 😓

[smfelsher]

@mathieuchopstm I confirmed on your PR thread, but I also wanted to thank you very much for your time and effort. I really appreciate all of you who contribute to open-source projects.