USB Power Event Panic

[teburd]

Describe the bug
A panic appears to occur on a USB power event.

To Reproduce
As best as I can tell, I've had a tough time reproducing this consistently, but using mcuboot master with zephyr and an app with a variety of stuff enabled via prj.conf seems to cause the problem sometimes.

My prj.conf for the app that causes the fault.

CONFIG_FLOAT=y
CONFIG_COMPILER_OPT="-ffast-math"

# GPIO Enable
CONFIG_GPIO=y

# Logging Config
CONFIG_LOG=y
CONFIG_LOG_PRINTK=y
CONFIG_LOG_BACKEND_RTT=y

CONFIG_ISR_STACK_SIZE=4096

# Workqueue stack needs to be larger for some tasks
CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=8192

## USB 
CONFIG_USB=y
CONFIG_USB_DEVICE_STACK=y
CONFIG_USB_DEVICE_PRODUCT="The Boss"
CONFIG_USB_UART_CONSOLE=y
CONFIG_UART_INTERRUPT_DRIVEN=y
CONFIG_UART_LINE_CTRL=y

## RTT and SystemView 
CONFIG_USE_SEGGER_RTT=n
CONFIG_RTT_CONSOLE=y
CONFIG_SEGGER_SYSTEMVIEW=n

# Debug help
CONFIG_DEBUG=n
CONFIG_ASSERT=n
CONFIG_OUTPUT_DISASSEMBLY=y
CONFIG_STACK_CANARIES=n
CONFIG_STACK_SENTINEL=n
CONFIG_DEBUG_INFO=y
CONFIG_INIT_STACKS=n
CONFIG_STACK_USAGE=n

# Enable mcumgr.
CONFIG_MCUMGR=y
CONFIG_MCUMGR_SMP_BT=y
#CONFIG_MCUMGR_SMP_SHELL=n
#CONFIG_MCUMGR_SMP_UART=y
CONFIG_MCUMGR_CMD_FS_MGMT=y
CONFIG_MCUMGR_CMD_IMG_MGMT=y
CONFIG_MCUMGR_CMD_OS_MGMT=y
CONFIG_MCUMGR_CMD_STAT_MGMT=y

# Ensure an MCUboot-compatible binary is generated.
CONFIG_BOOTLOADER_MCUBOOT=n

# Setup watchdog support
CONFIG_WATCHDOG=n

# Enable ADC for battery level monitoring
CONFIG_ADC=y
CONFIG_ADC_0=y
CONFIG_ADC_NRFX_SAADC=y
#CONFIG_ADC_NRFX_ADC_CHANNEL_COUNT=1

# Setup flash access and file system settings
CONFIG_FLASH=y
CONFIG_FLASH_PAGE_LAYOUT=y
CONFIG_SOC_FLASH_NRF_RADIO_SYNC=y
CONFIG_MPU_ALLOW_FLASH_WRITE=y
CONFIG_FILE_SYSTEM=y
CONFIG_FILE_SYSTEM_NFFS=y
CONFIG_FS_NFFS_FLASH_DEV_NAME="NRF_FLASH_DRV_NAME"
CONFIG_FS_NFFS_NUM_FILES=4
CONFIG_FS_NFFS_NUM_DIRS=4
CONFIG_FS_NFFS_NUM_INODES=1024
CONFIG_FS_NFFS_NUM_BLOCKS=1024
CONFIG_FS_NFFS_NUM_CACHE_INODES=1
CONFIG_FS_NFFS_NUM_CACHE_BLOCKS=1
CONFIG_FILE_SYSTEM_NFFS=y
CONFIG_NFFS_FILESYSTEM_MAX_AREAS=12

# Settings
CONFIG_SETTINGS=y
CONFIG_SETTINGS_FS_DIR="/nffs/settings"
CONFIG_SETTINGS_FS_FILE="/nffs/settings/run"

# Bluetooth Config
CONFIG_BT=y
#CONFIG_BT_PERIPHERAL=y
#CONFIG_BT_DEBUG_LOG=n
#CONFIG_BT_DEBUG_CONN=y
#CONFIG_BT_DEBUG_SETTINGS=y
#CONFIG_BT_DEBUG_GATT=y
#CONFIG_BT_DEBUG_ATT=y
#CONFIG_BT_DEBUG_L2CAP=y
#CONFIG_BT_DEBUG_HCI_CORE=y
#CONFIG_BT_DEBUG_HCI_DRIVER=y
#CONFIG_BT_DEBUG_MONITOR=n # dumps protocol on UART
#CONFIG_BT_CTLR_PROFILE_ISR=y
CONFIG_BT_DEVICE_NAME="My Device"
#CONFIG_BT_DEVICE_NAME_DYNAMIC=y
#CONFIG_BT_DEVICE_NAME_GATT_WRITABLE=y
#CONFIG_BT_DEVICE_NAME_MAX=64
CONFIG_BT_RX_BUF_COUNT=4
CONFIG_BT_RX_BUF_LEN=251
CONFIG_BT_RX_STACK_SIZE=2048
#CONFIG_BT_SETTINGS=n
CONFIG_BT_L2CAP_TX_BUF_COUNT=10
#CONFIG_BT_L2CAP_TX_FRAG_COUNT=4
CONFIG_BT_L2CAP_TX_MTU=251
#CONFIG_BT_CONN_TX_MAX=10
#CONFIG_BT_ATT_PREPARE_COUNT=10
CONFIG_BT_ATT_TX_MAX=10
#CONFIG_BT_SMP=n
#CONFIG_BT_PRIVACY=n
#CONFIG_BT_SIGNING=n
#CONFIG_BT_CTLR=y
CONFIG_BT_CTLR_TX_BUFFERS=10
CONFIG_BT_CTLR_RX_BUFFERS=4
CONFIG_BT_CTLR_TX_BUFFER_SIZE=251
CONFIG_BT_CTLR_DATA_LENGTH_MAX=251
CONFIG_BT_CTLR_ADVANCED_FEATURES=y
CONFIG_BT_CTLR_WORKER_PRIO=0
CONFIG_BT_CTLR_JOB_PRIO=0
CONFIG_BT_CTLR_PHY_2M=y #toggle suppoort of 2M phy
CONFIG_BT_CTLR_CONN_RSSI=y
CONFIG_BT_CTLR_SCAN_REQ_RSSI=y

# Bluetooth support of mcumgr requires a net_buf user_data size >= 7.
CONFIG_NET_BUF_USER_DATA_SIZE=16

# Required by the `taskstat` command.
CONFIG_THREAD_MONITOR=y

# Enable statistics and statistic names.
CONFIG_STATS=y
CONFIG_STATS_NAMES=y

CONFIG_I2C=y
CONFIG_I2C_NRFX=y
CONFIG_I2C_0=y
CONFIG_I2C_0_NRF_TWIM=y

CONFIG_SPI=y
CONFIG_SPI_NRFX=y
CONFIG_SPI_1=y
CONFIG_SPI_1_NRF_SPIM=y

CONFIG_SENSOR=y


# Magnetometer Sensor
CONFIG_LIS3MDL=y
CONFIG_LIS3MDL_TRIGGER=y
CONFIG_LIS3MDL_THREAD_PRIORITY=0
CONFIG_LIS3MDL_TRIGGER_OWN_THREAD=y
CONFIG_LIS3MDL_TRIGGER_IRQ=n
CONFIG_LIS3MDL_TRIGGER_GLOBAL_THREAD=n
CONFIG_LIS3MDL_DATA_RAW=y
CONFIG_LIS3MDL_DATA_CONVERTED=n
CONFIG_LIS3MDL_ODR="1000"
CONFIG_LIS3MDL_FS=4

# LP5521 LED controller
CONFIG_LED=y
CONFIG_LP5521=y

Expected behavior
No panics!

Impact
This prevents my application from working with mcuboot, which prevents OTA updates.

Screenshots or console output

GDB output as I was debugging this problem

(gdb) break usb_dc_nrfx_power_event_callback
Breakpoint 1 at 0x14a60: file /home/tburdick/src/zephyr/drivers/usb/device/usb_dc_nrfx.c, line 477.
(gdb) break usb_enable
Breakpoint 2 at 0x126a4: file /home/tburdick/src/zephyr/subsys/usb/usb_device.c, line 999.
(gdb) monitor reset 2
mResets core & peripherals using RESET pin.
(gdb) monitor reset
Resetting target
(gdb) c
Continuing.

Breakpoint 1, usb_dc_nrfx_power_event_callback (event=event@entry=NRF_POWER_EVENT_USBDETECTED) at /home/tburdick/src/zephyr/drivers/usb/device/usb_dc_nrfx.c:477
477		switch (event) {
(gdb) print usbd_ctx 
$1 = {status_cb = 0x0, attached = false, ready = false, usb_work = {_reserved = 0x0, handler = 0x0, flags = {0}}, work_queue = {_queue = {data_q = {head = 0x0, tail = 0x0}, {wait_q = {waitq = {{head = 0x0, next = 0x0}, {tail = 0x0, prev = 0x0}}}, poll_events = {{head = 0x0, 
            next = 0x0}, {tail = 0x0, prev = 0x0}}}}}, drv_lock = {wait_q = {waitq = {{head = 0x0, next = 0x0}, {tail = 0x0, prev = 0x0}}}, owner = 0x0, lock_count = 0, owner_orig_prio = 0}, ep_ctx = {{cfg = {cb = 0x0, max_sz = 0, en = false, addr = 0 '\000', 
        type = USB_DC_EP_CONTROL}, buf = {len = 0, block = {data = 0x0, id = {pool = 0, level = 0, block = 0}}, data = 0x0, curr = 0x0}, read_complete = false, read_pending = false, write_in_progress = false, write_fragmented = false} <repeats 18 times>}, ctrl_read_len = 0}
(gdb) break _Sys
_SysFatalErrorHandler  _SysNmiOnReset         
(gdb) break _SysFatalErrorHandler 
Breakpoint 3 at 0x156ac: file /home/tburdick/src/zephyr/arch/arm/core/sys_fatal_error_handler.c, line 52.
(gdb) c
Continuing.

Breakpoint 3, _SysFatalErrorHandler (reason=0, pEsf=0x200391f0 <_interrupt_stack+3960>) at /home/tburdick/src/zephyr/arch/arm/core/sys_fatal_error_handler.c:52
52		if (reason == _NANO_ERR_KERNEL_PANIC) {
(gdb) bt
#0  _SysFatalErrorHandler (reason=0, pEsf=0x200391f0 <_interrupt_stack+3960>) at /home/tburdick/src/zephyr/arch/arm/core/sys_fatal_error_handler.c:52
#1  0x00015636 in __usage_fault () at /home/tburdick/src/zephyr/arch/arm/core/fault_s.S:143
#2  <signal handler called>
#3  signal_poll_event (event=0x0, state=state@entry=4) at /home/tburdick/src/zephyr/kernel/poll.c:342
#4  0x000309a4 in _handle_obj_poll_events (events=events@entry=0x20027164 <usbd_ctx+28>, state=state@entry=4) at /home/tburdick/src/zephyr/kernel/poll.c:371
#5  0x0002f790 in handle_poll_events (state=4, queue=0x2002715c <usbd_ctx+20>) at /home/tburdick/src/zephyr/kernel/queue.c:119
#6  queue_insert (queue=queue@entry=0x2002715c <usbd_ctx+20>, prev=0x0, data=<optimized out>, alloc=alloc@entry=false) at /home/tburdick/src/zephyr/kernel/queue.c:179
#7  0x0002f7ee in k_queue_append (queue=queue@entry=0x2002715c <usbd_ctx+20>, data=<optimized out>) at /home/tburdick/src/zephyr/kernel/queue.c:193
#8  0x000141ac in usbd_evt_put (ev=<optimized out>) at /home/tburdick/src/zephyr/drivers/usb/device/usb_dc_nrfx.c:395
#9  0x00014a88 in usb_dc_nrfx_power_event_callback (event=event@entry=NRF_POWER_EVENT_USBDETECTED) at /home/tburdick/src/zephyr/drivers/usb/device/usb_dc_nrfx.c:501
#10 0x00013a56 in power_event_cb (event=NRF_POWER_EVENT_USBDETECTED) at /home/tburdick/src/zephyr/drivers/clock_control/nrf_power_clock.c:275
#11 _power_clock_isr (arg=0x0) at /home/tburdick/src/zephyr/drivers/clock_control/nrf_power_clock.c:415
#12 0x0001577a in _isr_wrapper () at /home/tburdick/src/zephyr/arch/arm/core/isr_wrapper.S:120
#13 <signal handler called>
#14 0x17fb7d56 in ?? ()
#15 0x28311824 in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb) 

Environment (please complete the following information):

• gcc 6.2.1

Additional context
It appears that sometimes a usb power event occurs before the usbd_ctx has been initialized from usb_dc_attach. I think that is the cause of the problem, because then the usb_work struct is likely to be uninitialized.

I'd guess this happens because the clock device is initialized before the usb device where the callback is initially setup in an IRQ, this IRQ must be occuring before the subsequent usb_enable is called.

Why that happens beyond my current understanding of zephyr and the usb device driver.