drivers: usb: device: raspberrypi_pico_usbd - use of uninitialized semaphore

[FlorianWeber1018]

Describe the bug

In some cases the write semaphore is used before it was initialized. This leads to a fatal error.
In my case this happens just after
irq_enable(USB_IRQ); (https://github.com/zephyrproject-rtos/zephyr/blob/main/drivers/usb/device/usb_dc_rpi_pico.c#L1076)

To Reproduce

configure a cdc-acm-uart on the usb device and restart the device (via gdb) till it just happens during boot.

Expected behavior

nothing should use a semaphore before it was initialized.

Environment (please complete the following information):

• OS: Linux in docker container on macOS host

Additional context

I use the usb interface for a cdc-acm-uart on a raspberryPi pico (rp2040). With the following configured options:
CONFIG_DEBUG=y
CONFIG_DEBUG_OPTIMIZATIONS=y
CONFIG_NO_OPTIMIZATIONS=y
CONFIG_LOG_SPEED=y
and it disappears or seems to happen less frequently if the compiler optimization is enabled.

[kartben]

@FlorianWeber1018 would you be able to send a PR, if you've identified where the missing initialization should happen, maybe?

[FlorianWeber1018]

@kartben No i am not that used to USB stuff. Thats why i have submitted this issue, hopefully that someone with a more detailed knowledge is looking on that.

[jfischer-no]

To Reproduce

configure a cdc-acm-uart on the usb device and restart the device (via gdb) till it just happens during boot.

I am not sure how to reproduce it. At least the backtrace would be very helpful. I see the irq_enable() is called too early, @FlorianWeber1018 can you please try #86102 if it fixes your problem.

[FlorianWeber1018]

386-interpreter-exec console "bt"
-> ~"#0  k_sys_fatal_error_handler (reason=0, esf=0x200105c4 <z_interrupt_stacks+1404>) at /workspaces/fancyProject/zephyr/kernel/fatal.c:44\n"
#0  k_sys_fatal_error_handler (reason=0, esf=0x200105c4 <z_interrupt_stacks+1404>) at /workspaces/fancyProject/zephyr/kernel/fatal.c:44
-> ~"#1  0x10021448 in z_fatal_error (reason=0, esf=0x200105c4 <z_interrupt_stacks+1404>) at /workspaces/fancyProject/zephyr/kernel/fatal.c:119\n"
#1  0x10021448 in z_fatal_error (reason=0, esf=0x200105c4 <z_interrupt_stacks+1404>) at /workspaces/fancyProject/zephyr/kernel/fatal.c:119
-> ~"#2  0x10016c22 in z_arm_fatal_error (reason=0, esf=0x200105c4 <z_interrupt_stacks+1404>) at /workspaces/fancyProject/zephyr/arch/arm/core/fatal.c:86\n"
#2  0x10016c22 in z_arm_fatal_error (reason=0, esf=0x200105c4 <z_interrupt_stacks+1404>) at /workspaces/fancyProject/zephyr/arch/arm/core/fatal.c:86
-> ~"#3  0x10016ffe in z_arm_fault (msp=536938008, psp=536936064, exc_return=4294967281, callee_regs=0xeb) at /workspaces/fancyProject/zephyr/arch/arm/core/cortex_m/fault.c:1080\n"
#3  0x10016ffe in z_arm_fault (msp=536938008, psp=536936064, exc_return=4294967281, callee_regs=0xeb) at /workspaces/fancyProject/zephyr/arch/arm/core/cortex_m/fault.c:1080
-> ~"#4  0x10017050 in z_arm_hard_fault () at /workspaces/fancyProject/zephyr/arch/arm/core/cortex_m/fault_s.S:102\n"
#4  0x10017050 in z_arm_hard_fault () at /workspaces/fancyProject/zephyr/arch/arm/core/cortex_m/fault_s.S:102
-> ~"#5  <signal handler called>\n"
#5  <signal handler called>
-> ~"#6  0x10042b4e in sys_dlist_remove (node=0x0) at /workspaces/fancyProject/zephyr/include/zephyr/sys/dlist.h:532\n"
#6  0x10042b4e in sys_dlist_remove (node=0x0) at /workspaces/fancyProject/zephyr/include/zephyr/sys/dlist.h:532
-> ~"#7  0x10042b96 in sys_dlist_get (list=0x20005974 <state+864>) at /workspaces/fancyProject/zephyr/include/zephyr/sys/dlist.h:553\n"
#7  0x10042b96 in sys_dlist_get (list=0x20005974 <state+864>) at /workspaces/fancyProject/zephyr/include/zephyr/sys/dlist.h:553
-> ~"#8  0x1002ab94 in z_handle_obj_poll_events (events=0x20005974 <state+864>, state=2) at /workspaces/fancyProject/zephyr/kernel/poll.c:462\n"
#8  0x1002ab94 in z_handle_obj_poll_events (events=0x20005974 <state+864>, state=2) at /workspaces/fancyProject/zephyr/kernel/poll.c:462
-> ~"#9  0x1004157a in handle_poll_events (sem=0x20005964 <state+848>) at /workspaces/fancyProject/zephyr/kernel/sem.c:88\n"
#9  0x1004157a in handle_poll_events (sem=0x20005964 <state+848>) at /workspaces/fancyProject/zephyr/kernel/sem.c:88
-> ~"#10 0x10023422 in z_impl_k_sem_give (sem=0x20005964 <state+848>) at /workspaces/fancyProject/zephyr/kernel/sem.c:111\n"
#10 0x10023422 in z_impl_k_sem_give (sem=0x20005964 <state+848>) at /workspaces/fancyProject/zephyr/kernel/sem.c:111
-> ~"#11 0x1003bc3c in k_sem_give (sem=0x20005964 <state+848>) at /workspaces/fancyProject/build/zephyr/include/generated/zephyr/syscalls/kernel.h:1119\n"
#11 0x1003bc3c in k_sem_give (sem=0x20005964 <state+848>) at /workspaces/fancyProject/build/zephyr/include/generated/zephyr/syscalls/kernel.h:1119
-> ~"#12 0x1001871c in udc_rpi_handle_buff_status () at /workspaces/fancyProject/zephyr/drivers/usb/device/usb_dc_rpi_pico.c:258\n"
#12 0x1001871c in udc_rpi_handle_buff_status () at /workspaces/fancyProject/zephyr/drivers/usb/device/usb_dc_rpi_pico.c:258
-> ~"#13 0x10018916 in udc_rpi_isr (arg=0x0) at /workspaces/fancyProject/zephyr/drivers/usb/device/usb_dc_rpi_pico.c:326\n"
#13 0x10018916 in udc_rpi_isr (arg=0x0) at /workspaces/fancyProject/zephyr/drivers/usb/device/usb_dc_rpi_pico.c:326
-> ~"#14 0x10017518 in _isr_wrapper () at /workspaces/fancyProject/zephyr/arch/arm/core/cortex_m/isr_wrapper.c:77\n"
#14 0x10017518 in _isr_wrapper () at /workspaces/fancyProject/zephyr/arch/arm/core/cortex_m/isr_wrapper.c:77
-> ~"#15 <signal handler called>\n"
#15 <signal handler called>
-> ~"#16 0x100171a4 in __NVIC_EnableIRQ (IRQn=5) at /workspaces/fancyProject/modules/hal/cmsis/CMSIS/Core/Include/core_cm0plus.h:749\n"
#16 0x100171a4 in __NVIC_EnableIRQ (IRQn=5) at /workspaces/fancyProject/modules/hal/cmsis/CMSIS/Core/Include/core_cm0plus.h:749
-> ~"#17 0x1003ac6a in arch_irq_enable (irq=5) at /workspaces/fancyProject/zephyr/arch/arm/core/cortex_m/irq_manage.c:39\n"
#17 0x1003ac6a in arch_irq_enable (irq=5) at /workspaces/fancyProject/zephyr/arch/arm/core/cortex_m/irq_manage.c:39
-> ~"#18 0x1001a5d2 in usb_rpi_init () at /workspaces/fancyProject/zephyr/drivers/usb/device/usb_dc_rpi_pico.c:1076\n"
#18 0x1001a5d2 in usb_rpi_init () at /workspaces/fancyProject/zephyr/drivers/usb/device/usb_dc_rpi_pico.c:1076
-> ~"#19 0x1002175a in z_sys_init_run_level (level=INIT_LEVEL_POST_KERNEL) at /workspaces/fancyProject/zephyr/kernel/init.c:371\n"
#19 0x1002175a in z_sys_init_run_level (level=INIT_LEVEL_POST_KERNEL) at /workspaces/fancyProject/zephyr/kernel/init.c:371
-> ~"#20 0x1002179c in bg_thread_main (unused1=0x0, unused2=0x0, unused3=0x0) at /workspaces/fancyProject/zephyr/kernel/init.c:519\n"
#20 0x1002179c in bg_thread_main (unused1=0x0, unused2=0x0, unused3=0x0) at /workspaces/fancyProject/zephyr/kernel/init.c:519
-> ~"#21 0x10033ad8 in z_thread_entry (entry=0x10021785 <bg_thread_main>, p1=0x0, p2=0x0, p3=0x0) at /workspaces/fancyProject/zephyr/lib/os/thread_entry.c:48\n"
#21 0x10033ad8 in z_thread_entry (entry=0x10021785 <bg_thread_main>, p1=0x0, p2=0x0, p3=0x0) at /workspaces/fancyProject/zephyr/lib/os/thread_entry.c:48
-> ~"#22 0x100173e2 in arch_switch_to_main_thread (main_thread=0x0, stack_ptr=0x20005ef0 <timeout_lock> \"\", _main=0x20005ef0 <timeout_lock>) at /workspaces/fancyProject/zephyr/arch/arm/core/cortex_m/thread.c:546\n"
#22 0x100173e2 in arch_switch_to_main_thread (main_thread=0x0, stack_ptr=0x20005ef0 <timeout_lock> "", _main=0x20005ef0 <timeout_lock>) at /workspaces/fancyProject/zephyr/arch/arm/core/cortex_m/thread.c:546
-> ~"#23 0x00000000 in ?? ()\n"
#23 0x00000000 in ?? ()
-> 386^done
{"output":"","token":386,"outOfBandRecord":[],"resultRecords":{"resultClass":"done","results":[]}}
387-stack-info-frame --thread 1 --frame 18
-> 387^done,frame={level="18",addr="0x1001a5d2",func="usb_rpi_init",file="/workspaces/fancyProject/zephyr/drivers/usb/device/usb_dc_rpi_pico.c",fullname="/workspaces/fancyProject/zephyr/drivers/usb/device/usb_dc_rpi_pico.c",line="1076",arch="armv6s-m"}
388-var-create --thread 1 --frame 18 watch_746cd73840c0256f8792f1e3e65b8b70acd7c4f2fdf83c043531dbbb7cd2ef7e @ "&tree.lessthan_fn"
-> 388^error,msg="-var-create: unable to create variable object"
watch -var-create: unable to create variable object (from var-create --thread 1 --frame 18 watch_746cd73840c0256f8792f1e3e65b8b70acd7c4f2fdf83c043531dbbb7cd2ef7e @ "&tree.lessthan_fn")389-var-create --thread 1 --frame 18 watch_1eb837abd5432246a5b7fe515d3a509ddc08acc08f1e3a7ab9238fed5587de88 @ "&queue.queue.lessthan_fn"
-> 389^error,msg="-var-create: unable to create variable object"
watch -var-create: unable to create variable object (from var-create --thread 1 --frame 18 watch_1eb837abd5432246a5b7fe515d3a509ddc08acc08f1e3a7ab9238fed5587de88 @ "&queue.queue.lessthan_fn")390-var-create --thread 1 --frame 18 watch_612f3cb150fa66268ae155099c255e902dd1158b1e046adcd53fcd301ccd4b59 @ "&queue->active"
-> 390^error,msg="-var-create: unable to create variable object"
watch -var-create: unable to create variable object (from var-create --thread 1 --frame 18 watch_612f3cb150fa66268ae155099c255e902dd1158b1e046adcd53fcd301ccd4b59 @ "&queue->active")391-var-create --thread 1 --frame 18 watch_03bcf0a67db4326701e8a19fe667aa3e76278b34ff19107d4418d1c566578092 @ "&w->dlnode"
-> 391^error,msg="-var-create: unable to create variable object"
watch -var-create: unable to create variable object (from var-create --thread 1 --frame 18 watch_03bcf0a67db4326701e8a19fe667aa3e76278b34ff19107d4418d1c566578092 @ "&w->dlnode")392-stack-list-variables --thread 1 --frame 18 --simple-values
-> 392^done,variables=[{name="ret",type="int",value="0"}]
393-var-update --thread 1 --frame 18 --all-values var_ret_4114
-> 393^done,changelist=[]

@jfischer-no is that what you need? (created with a94acf3 (main) after ~20 reboots)

[FlorianWeber1018]

@jfischer-no i have tested #86102. It seems to fix this issue.
Test procedure:
With the PR have rebooted 150 times without running in the fatal error in the backtrace above.
Without the PR the error happens after 29 reboots 2 times.

I think there is a high chance that it is fixed now.

[jfischer-no]

#12 0x1001871c in udc_rpi_handle_buff_status () at /workspaces/fancyProject/zephyr/drivers/usb/device/usb_dc_rpi_pico.c:258
-> ~"#13 0x10018916 in udc_rpi_isr (arg=0x0) at /workspaces/fancyProject/zephyr/drivers/usb/device/usb_dc_rpi_pico.c:326\n"
#13 0x10018916 in udc_rpi_isr (arg=0x0) at /workspaces/fancyProject/zephyr/drivers/usb/device/usb_dc_rpi_pico.c:326
-> ~"#14 0x10017518 in _isr_wrapper () at /workspaces/fancyProject/zephyr/arch/arm/core/cortex_m/isr_wrapper.c:77\n"
#14 0x10017518 in _isr_wrapper () at /workspaces/fancyProject/zephyr/arch/arm/core/cortex_m/isr_wrapper.c:77
-> ~"#15 <signal handler called>\n"
#15 <signal handler called>
-> ~"#16 0x100171a4 in __NVIC_EnableIRQ (IRQn=5) at /workspaces/fancyProject/modules/hal/cmsis/CMSIS/Core/Include/core_cm0plus.h:749\n"
#16 0x100171a4 in __NVIC_EnableIRQ (IRQn=5) at /workspaces/fancyProject/modules/hal/cmsis/CMSIS/Core/Include/core_cm0plus.h:749
-> ~"#17 0x1003ac6a in arch_irq_enable (irq=5) at /workspaces/fancyProject/zephyr/arch/arm/core/cortex_m/irq_manage.c:39\n"
#17 0x1003ac6a in arch_irq_enable (irq=5) at /workspaces/fancyProject/zephyr/arch/arm/core/cortex_m/irq_manage.c:39
-> ~"#18 0x1001a5d2 in usb_rpi_init () at /workspaces/fancyProject/zephyr/drivers/usb/device/usb_dc_rpi_pico.c:1076\n"

@FlorianWeber1018 As you can see above, the interrupt fires just after irq_enable() in usb_rpi_init(). #86102 should fix it.