usb:composite: data abort on second ums launch

usb:composite: data abort on second ums launch

[Zixun LI]

Hi,

I encountered a data abort on the 2nd "ums 0 mmc 0" command on
u-boot-at91 2024.07 with sam9x60-curiosity board.

U-Boot> ums 0 mmc 0
UMS: LUN 0, dev mmc 0, hwpart 0, sector 0x0, count 0x1d29000
CTRL+C - Operation aborted
U-Boot> ums 0 mmc 0
UMS: LUN 0, dev mmc 0, hwpart 0, sector 0x0, count 0x1d29000
data abort
pc : [<27f93428>]          lr : [<27ef7e80>]
reloc pc : [<23f16428>]    lr : [<23e7ae80>]
sp : 27ef4cf0  ip : a5200000     fp : 23f6915c
r10: deadbeef  r9 : 27ef7e80     r8 : 27f7d2a0
r7 : a5200000  r6 : 00000000     r5 : 00000000  r4 : 27f01668
r3 : 00000000  r2 : 00000000     r1 : 27fe1d88  r0 : 27f01668
Flags: nzCV  IRQs off  FIQs off  Mode SVC_32 (T)
Code: 45ac d017 68c5 4667 (60fd) 60af

From backtrace the abort happened in fREe_impl(), with some debugging
I've localized the abort in fact happened in fsg buffer allocation in
fsg_common_init() [1]

It looks like the buffer is not freed on driver unregister since
fsg_common_release() is only called if fsg_common_init() met an error.


[1] https://elixir.bootlin.com/u-boot/v2025.01/source/drivers/usb/gadget/f_mass_storage.c#L2511

Re: usb:composite: data abort on second ums launch

[Marek Vasut]

On 3/24/25 11:42 AM, Zixun LI wrote:
> Hi,
> 
> I encountered a data abort on the 2nd "ums 0 mmc 0" command on
> u-boot-at91 2024.07 with sam9x60-curiosity board.
> 
> U-Boot> ums 0 mmc 0
> UMS: LUN 0, dev mmc 0, hwpart 0, sector 0x0, count 0x1d29000
> CTRL+C - Operation aborted
> U-Boot> ums 0 mmc 0
> UMS: LUN 0, dev mmc 0, hwpart 0, sector 0x0, count 0x1d29000
> data abort
> pc : [<27f93428>]          lr : [<27ef7e80>]
> reloc pc : [<23f16428>]    lr : [<23e7ae80>]
> sp : 27ef4cf0  ip : a5200000     fp : 23f6915c
> r10: deadbeef  r9 : 27ef7e80     r8 : 27f7d2a0
> r7 : a5200000  r6 : 00000000     r5 : 00000000  r4 : 27f01668
> r3 : 00000000  r2 : 00000000     r1 : 27fe1d88  r0 : 27f01668
> Flags: nzCV  IRQs off  FIQs off  Mode SVC_32 (T)
> Code: 45ac d017 68c5 4667 (60fd) 60af
> 
>  From backtrace the abort happened in fREe_impl(), with some debugging
> I've localized the abort in fact happened in fsg buffer allocation in
> fsg_common_init() [1]
> 
> It looks like the buffer is not freed on driver unregister since
> fsg_common_release() is only called if fsg_common_init() met an error.
Can you reproduce this on u-boot/master too ?

Re: usb:composite: data abort on second ums launch

[Zixun LI]

On Mon, Mar 24, 2025 at 3:12 PM Marek Vasut <marex@denx.de> wrote:
> Can you reproduce this on u-boot/master too ?

Yes I can reproduce it on master 2025.04-244e61f, since fsg init/deinit code
are the same.

Re: usb:composite: data abort on second ums launch

[Mattijs Korpershoek]

Hi,

Thank you for the report.

On lun., mars 24, 2025 at 15:03, Marek Vasut <marex@denx.de> wrote:

> On 3/24/25 11:42 AM, Zixun LI wrote:
>> Hi,
>> 
>> I encountered a data abort on the 2nd "ums 0 mmc 0" command on
>> u-boot-at91 2024.07 with sam9x60-curiosity board.
>> 
>> U-Boot> ums 0 mmc 0
>> UMS: LUN 0, dev mmc 0, hwpart 0, sector 0x0, count 0x1d29000
>> CTRL+C - Operation aborted
>> U-Boot> ums 0 mmc 0
>> UMS: LUN 0, dev mmc 0, hwpart 0, sector 0x0, count 0x1d29000
>> data abort
>> pc : [<27f93428>]          lr : [<27ef7e80>]
>> reloc pc : [<23f16428>]    lr : [<23e7ae80>]
>> sp : 27ef4cf0  ip : a5200000     fp : 23f6915c
>> r10: deadbeef  r9 : 27ef7e80     r8 : 27f7d2a0
>> r7 : a5200000  r6 : 00000000     r5 : 00000000  r4 : 27f01668
>> r3 : 00000000  r2 : 00000000     r1 : 27fe1d88  r0 : 27f01668
>> Flags: nzCV  IRQs off  FIQs off  Mode SVC_32 (T)
>> Code: 45ac d017 68c5 4667 (60fd) 60af
>> 
>>  From backtrace the abort happened in fREe_impl(), with some debugging
>> I've localized the abort in fact happened in fsg buffer allocation in
>> fsg_common_init() [1]
>> 
>> It looks like the buffer is not freed on driver unregister since
>> fsg_common_release() is only called if fsg_common_init() met an error.
> Can you reproduce this on u-boot/master too ?

I've tried to reproduce this on master (2025.04-rc4-g244e61fbb7f5) and I
don't reproduce this with the VIM3 board using khadas-vim3_android_ab_defconfig:

U-Boot 2025.04-rc4-g244e61fbb7f5 (Mar 24 2025 - 18:15:36 +0100) khadas-vim3

Model: Khadas VIM3
SoC:   Amlogic Meson G12B (A311D) Revision 29:b (10:2)
DRAM:  2 GiB (effective 3.8 GiB)
Core:  407 devices, 36 uclasses, devicetree: separate
MMC:   mmc@ffe03000: 0, mmc@ffe05000: 1, mmc@ffe07000: 2
Loading Environment from MMC... MMC Device -1 not found
*** Warning - No MMC card found, using default environment

In:    usbkbd,serial
Out:   vidconsole,serial
Err:   vidconsole,serial
Net:   eth0: ethernet@ff3f0000

Hit any key to stop autoboot:  0
=> ums 0 mmc 2
UMS: LUN 0, dev mmc 2, hwpart 0, sector 0x0, count 0x3a3e000
|crq->brequest:0x0
CTRL+C - Operation aborted
=> ums 0 mmc 2
UMS: LUN 0, dev mmc 2, hwpart 0, sector 0x0, count 0x3a3e000
CTRL+C - Operation aborted
=>

I'll try to understand why it's behaving differently between the
sam9x60-curiosity and the vim3.

Thanks,
Mattijs

Re: usb:composite: data abort on second ums launch

[Zixun LI]

On Mon, Mar 24, 2025 at 6:21 PM Mattijs Korpershoek
<mkorpershoek@baylibre.com> wrote:
> I've tried to reproduce this on master (2025.04-rc4-g244e61fbb7f5) and I
> don't reproduce this with the VIM3 board using khadas-vim3_android_ab_defconfig:
>
> I'll try to understand why it's behaving differently between the
> sam9x60-curiosity and the vim3.

Thank you for your test, I think it's because VIM3 is a large SoC with
plenty of RAM
(SYS_MALLOC_LEN=0x08000000) while SAM9X60 is much smaller
(SYS_MALLOC_LEN=0x81000).

Each time when ums is called 2*FSG_BUFLEN, 256kB buffer is allocated
and it seems not
freed as fsg_common_release() is not called.

Zixun

Re: usb:composite: data abort on second ums launch

[Mattijs Korpershoek]

Hi Zixun,

On lun., mars 24, 2025 at 18:33, Zixun LI <admin@hifiphile.com> wrote:

> On Mon, Mar 24, 2025 at 6:21 PM Mattijs Korpershoek
> <mkorpershoek@baylibre.com> wrote:
>> I've tried to reproduce this on master (2025.04-rc4-g244e61fbb7f5) and I
>> don't reproduce this with the VIM3 board using khadas-vim3_android_ab_defconfig:
>>
>> I'll try to understand why it's behaving differently between the
>> sam9x60-curiosity and the vim3.
>
> Thank you for your test, I think it's because VIM3 is a large SoC with
> plenty of RAM
> (SYS_MALLOC_LEN=0x08000000) while SAM9X60 is much smaller
> (SYS_MALLOC_LEN=0x81000).

You are right, I've applied the following diff:

diff --git a/configs/khadas-vim3_android_ab_defconfig b/configs/khadas-vim3_android_ab_defconfig
index a078c5d363ae..c8d1cc69f1fb 100644
--- a/configs/khadas-vim3_android_ab_defconfig
+++ b/configs/khadas-vim3_android_ab_defconfig
@@ -3,7 +3,7 @@ CONFIG_SYS_BOARD="vim3"
 CONFIG_SYS_CONFIG_NAME="khadas-vim3_android"
 CONFIG_ARCH_MESON=y
 CONFIG_TEXT_BASE=0x01000000
-CONFIG_SYS_MALLOC_LEN=0x08000000
+CONFIG_SYS_MALLOC_LEN=0x81000
 CONFIG_NR_DRAM_BANKS=1
 CONFIG_HAS_CUSTOM_SYS_INIT_SP_ADDR=y
 CONFIG_CUSTOM_SYS_INIT_SP_ADDR=0x20000000

And with this, I can reproduce the issue you have reported:

U-Boot 2025.04-rc4-g0eeeeabb7cb1 (Mar 24 2025 - 18:37:26 +0100) khadas-vim3

Model: Khadas VIM3
SoC:   Amlogic Meson G12B (A311D) Revision 29:b (10:2)
DRAM:  2 GiB (effective 3.8 GiB)
Core:  407 devices, 36 uclasses, devicetree: separate
MMC:   mmc@ffe03000: 0, mmc@ffe05000: 1, mmc@ffe07000: 2
Loading Environment from MMC... MMC Device -1 not found
*** Warning - No MMC card found, using default environment

In:    usbkbd,serial
Out:   vidconsole,serial
Err:   vidconsole,serial
Net:   eth0: ethernet@ff3f0000

Hit any key to stop autoboot:  0
=> ums 0 mmc 2
UMS: LUN 0, dev mmc 2, hwpart 0, sector 0x0, count 0x3a3e000
|crq->brequest:0x0
CTRL+C - Operation aborted
=> ums 0 mmc 2
UMS: LUN 0, dev mmc 2, hwpart 0, sector 0x0, count 0x3a3e000
"Synchronous Abort" handler, esr 0x96000004, far 0xfffffffff2ea40f0
elr: 000000000102ddf4 lr : 000000000105c828 (reloc)
elr: 00000000f2f34df4 lr : 00000000f2f63828
x0 : 0000000100000000 x1 : 0000000100000000
x2 : 0000000000000000 x3 : fffffffff2ea40e0
x4 : 00000000f2fca1b8 x5 : 00000000f2ea40e0
x6 : 00000000f2fca1c8 x7 : 00000000f2ee6780
x8 : 000000000000003f x9 : 0000000000000004
x10: 0000000000000058 x11: 00000000000058c4
x12: 0000000000000000 x13: 00000000f2e62800
x14: 00000000f4ec0040 x15: 0000000000000000
x16: 00000000f2f63684 x17: 0000000000c0c0c0
x18: 00000000f2e75e00 x19: 00000000f2ea4010
x20: 00000000fffffff4 x21: 00000000f2e9d500
x22: 00000000f2ea40f0 x23: 00000000f2ea4050
x24: 00000000f2f62ebc x25: 00000000f2fd0000
x26: 00000000f2ea1cd0 x27: 0000000000000000
x28: 0000000000000000 x29: 00000000f2e62290

Code: d00004a6 910720c6 cb000063 8b000021 (f9400860)
Resetting CPU ...

resetting ...

>
> Each time when ums is called 2*FSG_BUFLEN, 256kB buffer is allocated
> and it seems not
> freed as fsg_common_release() is not called.
>
> Zixun

Re: usb:composite: data abort on second ums launch

[Mattijs Korpershoek]

Hi Zixun, Marek,

On lun., mars 24, 2025 at 18:40, Mattijs Korpershoek <mkorpershoek@baylibre.com> wrote:

> Hi Zixun,
>
> On lun., mars 24, 2025 at 18:33, Zixun LI <admin@hifiphile.com> wrote:
>
> resetting ...

[...]

>
>>
>> Each time when ums is called 2*FSG_BUFLEN, 256kB buffer is allocated
>> and it seems not
>> freed as fsg_common_release() is not called.

There are quite a few things that are wrong in
drivers/usb/gadget/f_mass_storage.c

1. The "Synchronous Abort" exception happens because we call
   kfree(common->luns); and common->luns is not allocated via
   malloc/kmalloc.

2. We use a kref member that's unused and can be removed

3. There is a memory leak (as reported by Zixun) when unbind() is
   called. We should call fsg_common_release().

I will send a series to fix this.

Zixun, thanks again for reporting this and helping me reproduce!

Mattijs

>>
>> Zixun

Re: usb:composite: data abort on second ums launch

[Mattijs Korpershoek]

Hi Zixun,

On jeu., mars 27, 2025 at 14:46, Mattijs Korpershoek <mkorpershoek@baylibre.com> wrote:

> Hi Zixun, Marek,
>
> On lun., mars 24, 2025 at 18:40, Mattijs Korpershoek <mkorpershoek@baylibre.com> wrote:
>
>> Hi Zixun,
>>
>> On lun., mars 24, 2025 at 18:33, Zixun LI <admin@hifiphile.com> wrote:
>>
>> resetting ...
>
> [...]
>
>>
>>>
>>> Each time when ums is called 2*FSG_BUFLEN, 256kB buffer is allocated
>>> and it seems not
>>> freed as fsg_common_release() is not called.
>
> There are quite a few things that are wrong in
> drivers/usb/gadget/f_mass_storage.c
>
> 1. The "Synchronous Abort" exception happens because we call
>    kfree(common->luns); and common->luns is not allocated via
>    malloc/kmalloc.
>
> 2. We use a kref member that's unused and can be removed
>
> 3. There is a memory leak (as reported by Zixun) when unbind() is
>    called. We should call fsg_common_release().
>
> I will send a series to fix this.

Series send out here:
https://lore.kernel.org/u-boot/20250328-ums-gadget-leak-v1-0-3b677db99bde@baylibre.com

Available on patchwork:
https://patchwork.ozlabs.org/project/uboot/patch/20250328-ums-gadget-leak-v1-0-3b677db99bde@baylibre.com/

If you could have a look and test it yourself, that would be greatly
appreciated.

If doing so, you can reply to the above thread with: "Tested-by: Name <email>"

>
> Zixun, thanks again for reporting this and helping me reproduce!
>
> Mattijs
>
>>>
>>> Zixun