Task watchdog boot-loop when debug log messages enabled

[vlucent]

Config

on platformio, tested with pioarduino: 53.03.13 (arduino core 3.3.9) and 55.03.39 (arduino core 3.3.9)
board: esp32-s3-devkitc-1

Reproduce

app: examples\NimBLE_Scan_Continuous
single change to nimconfig.h:

#define MYNEWT_VAL_NIMBLE_CPP_LOG_LEVEL 4

Logs

pioarduino v53.03.13 (arduino core 3.3.9)

E (10482) task_wdt: Task watchdog got triggered. The following tasks/users did not reset the watchdog in time:
E (10482) task_wdt:  - IDLE0 (CPU 0)
E (10482) task_wdt: Tasks currently running:
E (10482) task_wdt: CPU 0: nimble_host
E (10482) task_wdt: CPU 1: loopTask
E (10482) task_wdt: Aborting.
E (10482) task_wdt: Print CPU 0 (current core) backtrace


Backtrace: 0x42003be6:0x3fcb40f0 0x4200772d:0x3fcb4170 0x4200c461:0x3fcb41e0 0x4200c2ef:0x3fcb4220 0x4200c6d3:0x3fcb4240 0x4200b5a5:0x3fcb4260 0x42011b35:0x3fcb4280 0x42002ecc:0x3fcb42a0 0x4038089a:0x3fcb42c0
  #0  0x42003be6 in NimBLEScan::handleGapEvent(ble_gap_event*, void*) at lib/NimBLE-Arduino/src/nimble/porting/npl/freertos/include/nimble/nimble_npl_os.h:642
      (inlined by) NimBLEScan::handleGapEvent(ble_gap_event*, void*) at lib/NimBLE-Arduino/src/NimBLEScan.cpp:275
  #1  0x4200772d in ble_gap_disc_report at lib/NimBLE-Arduino/src/nimble/nimble/host/src/ble_gap.c:1018
      (inlined by) ble_gap_rx_adv_report at lib/NimBLE-Arduino/src/nimble/nimble/host/src/ble_gap.c:1607
  #2  0x4200c461 in ble_hs_hci_evt_le_adv_rpt at lib/NimBLE-Arduino/src/nimble/nimble/host/src/ble_hs_hci_evt.c:564
  #3  0x4200c2ef in ble_hs_hci_evt_le_meta at lib/NimBLE-Arduino/src/nimble/nimble/host/src/ble_hs_hci_evt.c:360
  #4  0x4200c6d3 in ble_hs_hci_evt_process at lib/NimBLE-Arduino/src/nimble/nimble/host/src/ble_hs_hci_evt.c:1109
  #5  0x4200b5a5 in ble_hs_event_rx_hci_ev at lib/NimBLE-Arduino/src/nimble/nimble/host/src/ble_hs.c:522
  #6  0x42011b35 in ble_npl_event_run at lib/NimBLE-Arduino/src/nimble/porting/npl/freertos/include/nimble/nimble_npl_os.h:493
      (inlined by) nimble_port_run at lib/NimBLE-Arduino/src/nimble/porting/nimble/src/nimble_port.c:287
  #7  0x42002ecc in NimBLEDevice::host_task(void*) at lib/NimBLE-Arduino/src/NimBLEDevice.cpp:882
  #8  0x4038089a in vPortTaskWrapper at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:139


ELF file SHA256: 4891b0e99

Rebooting...
ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0xc (RTC_SW_CPU_RST),boot:0x2b (SPI_FAST_FLASH_BOOT)
Saved PC:0x40376dc1
  #0  0x40376dc1 in esp_restart_noos at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/esp_system/port/soc/esp32s3/system_internal.c:158

SPIWP:0xee
mode:DIO, clock div:1
load:0x3fce2820,len:0x1188
load:0x403c8700,len:0x4
load:0x403c8704,len:0xbf0
load:0x403cb700,len:0x30e4
entry 0x403c88ac
D NimBLEDevice: Starting NimBLE-Arduino 3.0.0-dev
I NimBLEDevice: NimBLE Started!
I NimBLEDevice: NimBle host synced.
D NimBLEDevice: Initialized
D NimBLEScan: >> start: duration=30000
D NimBLEScan: Scan started
D NimBLEScan: << start()
Scanning...
I NimBLEScan: New advertiser: XX:XX:XX:XX:XX:XX
Discovered Device: Name: , Address: XX:XX:XX:XX:XX:XX, manufacturer data: XXX...
Device result: Name: , Address: XX:XX:XX:XX:XX:XX, manufacturer data: XXX...
D NimBLEScan: erase device: XX:XX:XX:XX:XX:XX
I NimBLEScan: New advertiser: XX:XX:XX:XX:XX:XX
Discovered Device: Name: , Address: XX:XX:XX:XX:XX:XX, manufacturer data: XXX...
E (10393) task_wdt: Task watchdog got triggered. The following tasks/users did not reset the watchdog in time:
E (10393) task_wdt:  - IDLE0 (CPU 0)
E (10393) task_wdt: Tasks currently running:
E (10393) task_wdt: CPU 0: nimble_host
E (10393) task_wdt: CPU 1: loopTask
E (10393) task_wdt: Aborting.
E (10393) task_wdt: Print CPU 0 (current core) backtrace

pioarduino v55.03.39 (arduino core 3.3.9)

E (10491) task_wdt: Task watchdog got triggered. The following tasks/users did not reset the watchdog in time:
E (10491) task_wdt:  - IDLE0 (CPU 0)
E (10491) task_wdt: Tasks currently running:
E (10491) task_wdt: CPU 0: nimble_host
E (10491) task_wdt: CPU 1: loopTask
E (10491) task_wdt: Aborting.
E (10491) task_wdt: Print CPU 0 (current core) backtrace




Backtrace: 0x420058fd:0x3fcae850 0x4200959d:0x3fcae8b0 0x4200e40b:0x3fcae920 0x4200e2a3:0x3fcae960 0x4200e68b:0x3fcae980 0x4200d565:0x3fcae9a0 0x42014529:0x3fcae9c0 0x42004a28:0x3fcae9e0 0x4037ffc1:0x3fcaea00




ELF file SHA256: f1ee3418e

Rebooting...
ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0xc (RTC_SW_CPU_RST),boot:0xb (SPI_FAST_FLASH_BOOT)
Saved PC:0x4037f595
SPIWP:0xee
mode:DIO, clock div:1
load:0x3fce2820,len:0x10cc
load:0x403c8700,len:0xc2c
load:0x403cb700,len:0x30c0
entry 0x403c88b8
D NimBLEDevice: Starting NimBLE-Arduino 3.0.0-dev
I NimBLEDevice: NimBLE Started!
I NimBLEDevice: NimBle host synced.
D NimBLEDevice: Initialized
D NimBLEScan: >> start: duration=30000
D NimBLEScan: Scan started
D NimBLEScan: << start()
Scanning...
I NimBLEScan: New advertiser: XX:XX:XX:XX:XX:XX
Discovered Device: Name: , Address: XX:XX:XX:XX:XX:XX, serviceUUID: 0xbeef
Service Data:
UUID: 0xbeef, Data: 
E (10393) task_wdt: Task watchdog got triggered. The following tasks/users did not reset the watchdog in time:
E (10393) task_wdt:  - IDLE0 (CPU 0)
E (10393) task_wdt: Tasks currently running:
E (10393) task_wdt: CPU 0: nimble_host
E (10393) task_wdt: CPU 1: loopTask
E (10393) task_wdt: Aborting.
E (10393) task_wdt: Print CPU 0 (current core) backtrace

Other Observations

problem goes away once the debug log flag is disabled. problem did not occur with NimBLE-Arduino 2.5.0

[vlucent]

I think I figured it out. It's because this function is calling itself in an infinite recursion.

static inline ble_npl_error_t
ble_npl_time_ticks_to_ms(ble_npl_time_t ticks, uint32_t *out_ms)
{
    return ble_npl_time_ticks_to_ms(ticks, out_ms);
}

https://github.com/h2zero/NimBLE-Arduino/blame/edf1b9e1f635dc97e16b175857ccfdba0d6d37b3/src/nimble/porting/npl/freertos/include/nimble/nimble_npl_os.h#L651-L655