CFG_TUSB_DEBUG=2 Serial1 deadlock on nRF52

[tlyu]

Operating System

MacOS

Board

Feather nRF52840 Express

Firmware

examples/HID/hid_boot_keyboard

What happened ?

Building the hid_boot_keyboard sketch on nRF52 (tested with Feather nRF52840 Express, but I think ItsyBitsy nRF52840 has the same problem) with debug level 2 and debug port Serial1 (in the Arduino IDE Tools menu) causes an apparent deadlock during TinyUSB initialization.

My current debugging setup (Blackmagic Probe) doesn't have RTOS or threading support, so I can't confirm whether there is another thread that's deadlocking somehow. I can try to get PyOCD on a Pico or something eventually, which should have the thread support, but that might take a while.

This might be a regression in 1.6.1 vs 1.6.0 of the nRF52 core, but I haven't confirmed that yet.

How to reproduce ?

Install Adafruit_nRF52_Arduino 1.6.1 in the Arduino IDE. Select Debug Level 2 and Debug Port Serial1. Compile and upload the hid_boot_keyboard sketch. Monitor Serial1 during boot, and observe that the debug output halts before the host enumerates the board.

Debug Log as txt file (LOG/CFG_TUSB_DEBUG=2)

Debug output on Serial1

USBD init on controller 0
sizeof(usbd_device_t) = 56
sizeof(dcd_event_t) = 12
sizeof(tu_fifo_t) = 20
sizeof(tu_edpt_stream_t) = 112
CDC init
MSC init
HID init
VIDEO init
MIDI init
VENDOR init
dcd init
Power USB event: Detected

Backtrace in GDB:

#0  0x00031132 in vListInsert (pxList=pxList@entry=0x2000a1bc,
    pxNewListItem=0x200076f0 <vApplicationGetIdleTaskMemory::xIdleTaskTCB+24>)
    at /Users/tlyu/Library/Arduino15/packages/adafruit/hardware/nrf52/1.6.1/cores/nRF5/freertos/Source/list.c:150
#1  0x0002f300 in vTaskPlaceOnEventList (
    pxEventList=pxEventList@entry=0x2000a1bc, xTicksToWait=4294967295)
    at /Users/tlyu/Library/Arduino15/packages/adafruit/hardware/nrf52/1.6.1/cores/nRF5/freertos/Source/tasks.c:2935
#2  0x0002e474 in xQueueSemaphoreTake (xQueue=0x2000a198,
    xTicksToWait=<optimized out>, xTicksToWait@entry=4294967295)
    at /Users/tlyu/Library/Arduino15/packages/adafruit/hardware/nrf52/1.6.1/cores/nRF5/freertos/Source/queue.c:1533
#3  0x00030986 in Uart::write (size=<optimized out>, buffer=<optimized out>,
    this=<optimized out>)
    at /Users/tlyu/Library/Arduino15/packages/adafruit/hardware/nrf52/1.6.1/cores/nRF5/Uart.cpp:243
#4  Uart::write (this=0x2000762c <Serial1>,
    buffer=0x2003fe50 "Power USB event: Ready\r\n",
    buffer@entry=0x2003fe30 "<r", size=24)
    at /Users/tlyu/Library/Arduino15/packages/adafruit/hardware/nrf52/1.6.1/cores/nRF5/Uart.cpp:232
#5  0x00026814 in Print::write (str=0x2003fe30 "<r", this=<optimized out>)
    at /Users/tlyu/Library/Arduino15/packages/adafruit/hardware/nrf52/1.6.1/cores/nRF5/Print.h:53
--Type <RET> for more, q to quit, c to continue without paging--
#6  log_printf (format=0x35f40 "Power USB event: %s\r\n")
    at /Users/tlyu/Library/Arduino15/packages/adafruit/hardware/nrf52/1.6.1/libraries/Adafruit_TinyUSB_Arduino/src/arduino/Adafruit_TinyUSB_API.cpp:89
#7  0x0002ce36 in tusb_hal_nrf_power_event (event=2)
    at /Users/tlyu/Library/Arduino15/packages/adafruit/hardware/nrf52/1.6.1/libraries/Adafruit_TinyUSB_Arduino/src/portable/nordic/nrf5x/dcd_nrf5x.c:985
#8  <signal handler called>
#9  0x0002fdc2 in vPortStartFirstTask ()
    at /Users/tlyu/Library/Arduino15/packages/adafruit/hardware/nrf52/1.6.1/cores/nRF5/freertos/portable/GCC/nrf52/port.c:53
#10 0x0002fad2 in xPortStartScheduler ()
    at /Users/tlyu/Library/Arduino15/packages/adafruit/hardware/nrf52/1.6.1/cores/nRF5/freertos/portable/CMSIS/nrf52/port_cmsis.c:240
#11 0x200076d8 in _loopHandle ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

The normal debug trace (via SEGGER RTT) on this host continues with:

Power USB event: Detected
Power USB event: Ready
USBD Bus Reset : Full Speed

USBD Setup Received 80 06 00 01 00 00 08 00
  Get Descriptor Device
  Queue EP 80 with 8 bytes ...
USBD Xfer Complete on EP 80 with 8 bytes
  Queue EP 00 with 0 bytes ...
USBD Xfer Complete on EP 00 with 0 bytes
USBD Bus Reset : Full Speed

etc.

I had to fix a few bugs in the SEGGER RTT support to get that to work.

Screenshots

No response

I have checked existing issues, dicussion and documentation

• I confirm I have checked existing issues, dicussion and documentation.

[HiFiPhile]

Hi, your issue involved Arduino which isn't covered by this repo. Please try to reproduce with stock examples:
https://github.com/hathach/tinyusb/tree/master/examples/device

[tlyu]

You might be correct that it's limited to the Arduino library.

However, upon investigating a bit more, it seems that tusb_hal_nrf_power_event calls TU_LOG from inside an ISR.

Is the tu_printf logging function expected to be ISR-safe? If so, it doesn't seem to be documented as a requirement.

The nRF52 Arduino core seems to have some issues with Serial1 being used from within an ISR.

Examining the state of the FreeRTOS task list suggests that it has gotten corrupted by turning into a loop, possibly due to calling non-ISR synchronization primitives from within an ISR.

[tlyu]

Confirmed that LOG=2 with examples/device/hid_boot_interface appears to function correctly, producing debug logs without deadlocking. I'll open an issue with the Arduino library.

I would still like some clarification about whether tu_printf is expected to be ISR-safe.

[HiFiPhile]

Is the tu_printf logging function expected to be ISR-safe? If so, it doesn't seem to be documented as a requirement.
The nRF52 Arduino core seems to have some issues with Serial1 being used from within an ISR.

Yes it should be ISR safe, while documentation is a bit lacking...

Meanwhile even for built-in logging interrupt lock is also missing:

tinyusb/hw/bsp/board.c

Line 49 in ccc7a36

TU_ATTR_USED int sys_write(int fhdl, const char *buf, size_t count) {