NRF5x startup race condition between VBUS interrupt and stack initialization

Operating System

Linux

Board

pca10095 should be same for pca10056 or other NRF

Firmware

TinyUSB 0.12.0

What happened ?

Board initialization for NRF5x (board_init() or equivalent) enables VBUS interrupt. Later USB stack is initialized in tusb_init(). If VBUS interrupt fires before tusb_init() finishes, it can enable normal USB interrupt before tusb_init() would do it. Then normal USB interrupt tries to post BUS RESET event and _usbd_q may not be ready yet and that can cause system crash or other unpredictable behavior depending on system used. Since this a race condition it does not happens all the time but enough to take it seriously.

Same scenario was observed in DA146xx driver when it was work in progress, now it is taken care of there.

How to reproduce ?

Similar result should be possible with normal examples. In my case this can be observed when system starts from software reset after DFU finishes so device was connected to VBUS whole time.

Debug Log

void tusb_hal_nrf_power_event (uint32_t event)
{
...
    case USB_EVT_READY:
...
      // Enable interrupt, priorities should be set by application
      NVIC_ClearPendingIRQ(USBD_IRQn);
      NVIC_EnableIRQ(USBD_IRQn); // <- Enables interrupt before tud_init() calls `dcd_int_enable(rhport);`
...

      // Enable pull up
      NRF_USBD->USBPULLUP = 1; // <- This can trigger BUS reset on bus before tud_init() ends

this in turn can start handling bus reset interrupt before tusb_init() ends. In my case mynewt specific queue used for posting events to USB task is not created yet. Here is reference stack trace where it's visible that USBD_IRQHandler was called before tusb_init() wanted interrupt to be enabled.

#0  0x0002a148 in os_memblock_get (mp=mp@entry=0xc) at repos/apache-mynewt-core/kernel/os/src/os_mempool.c:340
#1  0x000326de in osal_queue_send (in_isr=<optimized out>, data=0x2007fda4, qhdl=0x0) at repos/tinyusb/src/osal/osal_mynewt.h:153
#2  dcd_event_handler (event=event@entry=0x2007fda4, in_isr=<optimized out>) at repos/tinyusb/src/device/usbd.c:1132
#3  0x00032768 in dcd_event_bus_reset (rhport=rhport@entry=0 '\000', speed=speed@entry=TUSB_SPEED_FULL, in_isr=in_isr@entry=true) at repos/tinyusb/src/device/usbd.c:1147
#4  0x00033702 in dcd_int_handler (rhport=rhport@entry=0 '\000') at repos/tinyusb/src/portable/nordic/nrf5x/dcd_nrf5x.c:614
#5  0x00028ce4 in USBD_IRQHandler () at repos/apache-mynewt-core/hw/usb/tinyusb/nrf53/src/nrf53.c:41
#6  <signal handler called>
#7  os_mempool_init_internal (mp=0x20003078 <_usbd_qdef+12>, mp@entry=0x2000306c <_usbd_qdef>, blocks=16, block_size=<optimized out>, membuf=<optimized out>, name=name@entry=0x40688 "usbd queue", flags=flags@entry=0 '\000') at repos/apache-mynewt-core/kernel/os/src/os_mempool.c:164
#8  0x0002a0dc in os_mempool_init (mp=mp@entry=0x2000306c <_usbd_qdef>, blocks=<optimized out>, block_size=<optimized out>, membuf=<optimized out>, name=name@entry=0x40688 "usbd queue") at repos/apache-mynewt-core/kernel/os/src/os_mempool.c:184
#9  0x00032458 in osal_queue_create (qdef=0x2000306c <_usbd_qdef>) at repos/tinyusb/src/osal/osal_mynewt.h:129
#10 tud_init (rhport=rhport@entry=0 '\000') at repos/tinyusb/src/device/usbd.c:421
#11 0x00033a4c in tusb_init () at repos/tinyusb/src/tusb.c:41
#12 0x00028c04 in tinyusb_start () at repos/apache-mynewt-core/hw/usb/tinyusb/src/tinyusb.c:63
#13 0x0002680e in sysinit_app () at bin/targets/nordic_pca10095-btshell/generated/src/nordic_pca10095-btshell-sysinit-app.c:98
#14 0x0000e2b4 in main (argc=<error reading variable: value has been optimized out>, argv=<error reading variable: value has been optimized out>) at repos/apache-mynewt-nimble/apps/btshell/src/main.c:2570
#15 0x0002916e in os_main (arg=<optimized out>) at repos/apache-mynewt-core/kernel/os/src/os.c:182
#16 0x00028d58 in tinyusb_hardware_init () at repos/apache-mynewt-core/hw/usb/tinyusb/nrf53/src/nrf53.c:106

Screenshots

No response

hathach / tinyusb