BLE advertising stops almost immediately

[FrigoEU]

I've been trying to get this library up and running for a while now on multiple IDF versions (4.4 and 5.1 most recently) but keep running into the same issue. I'm running the ble_server.rs verbatim, on an ESP-WROOM-32, ESP-WROOM-32E and ESP32S3, the advertising starts and seems to work fine, but after less than a second (I think?) it shuts down. I'll then reset my ESP and the same thing happens: advertising starts and immediately stops. The full logs on restart (currently running 5.1, logs on 4.4 were very similar/the same):

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:7104
0x3fff0030 - g_ticks_per_us_app
    at ??:??
load:0x40078000,len:15576
0x40078000 - __udivmoddi4
    at ??:??
load:0x40080400,len:4
0x40080400 - _init
    at ??:??
ho 8 tail 4 room 4
load:0x40080404,len:3876
0x40080404 - _iram_text_start
    at ??:??
entry 0x4008064c
0x4008064c - _iram_text_start
    at ??:??
I (31) boot: ESP-IDF v5.1-beta1-378-gea5e0ff298-dirt 2nd stage bootloader
I (31) boot: compile time Jun  7 2023 07:48:23
I (33) boot: Multicore bootloader
I (37) boot: chip revision: v3.1
I (41) boot.esp32: SPI Speed      : 40MHz
I (46) boot.esp32: SPI Mode       : DIO
I (50) boot.esp32: SPI Flash Size : 8MB
I (55) boot: Enabling RNG early entropy source...
I (60) boot: Partition Table:
I (64) boot: ## Label            Usage          Type ST Offset   Length
I (71) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (79) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (86) boot:  2 factory          factory app      00 00 00010000 00200000
I (94) boot: End of partition table
I (98) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=30660h (198240) map
I (178) esp_image: segment 1: paddr=00040688 vaddr=3ffbdb60 size=045c4h ( 17860) load
I (185) esp_image: segment 2: paddr=00044c54 vaddr=40080000 size=0b3c4h ( 46020) load
I (205) esp_image: segment 3: paddr=00050020 vaddr=400d0020 size=90214h (590356) map
I (418) esp_image: segment 4: paddr=000e023c vaddr=4008b3c4 size=0ce40h ( 52800) load
I (452) boot: Loaded app from partition at offset 0x10000
I (452) boot: Disabling RNG early entropy source...
I (464) cpu_start: Multicore app
I (464) cpu_start: Pro cpu up.
I (464) cpu_start: Starting app cpu, entry point is 0x4008224c
0x4008224c - call_start_cpu1
    at /home/simon/rust-projects/esp32-test/.embuild/espressif/esp-idf/v5.1.1/components/esp_system/port/cpu_start.c:154
I (0) cpu_start: App cpu up.
I (482) cpu_start: Pro cpu start user code
I (482) cpu_start: cpu freq: 160000000 Hz
I (482) cpu_start: Application information:
I (487) cpu_start: Project name:     libespidf
I (492) cpu_start: App version:      1
I (497) cpu_start: Compile time:     Jan  1 1980 00:00:00
I (503) cpu_start: ELF file SHA256:  0000000000000000...
I (509) cpu_start: ESP-IDF:          v5.1.1
I (514) cpu_start: Min chip rev:     v0.0
I (518) cpu_start: Max chip rev:     v3.99 
I (523) cpu_start: Chip rev:         v3.1
I (528) heap_init: Initializing. RAM available for dynamic allocation:
I (535) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (541) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (547) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (553) heap_init: At 3FFC5190 len 0001AE70 (107 KiB): DRAM
I (560) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (566) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (572) heap_init: At 40098204 len 00007DFC (31 KiB): IRAM
I (580) spi_flash: detected chip: gd
I (583) spi_flash: flash io: dio
W (587) rmt(legacy): legacy driver is deprecated, please migrate to `driver/rmt_tx.h` and/or `driver/rmt_rx.h`
W (597) pcnt(legacy): legacy driver is deprecated, please migrate to `driver/pulse_cnt.h`
W (606) timer_group: legacy driver is deprecated, please migrate to `driver/gptimer.h`
I (615) coexist: coex firmware version: 80b0d89
I (621) app_start: Starting scheduler on CPU0
I (625) app_start: Starting scheduler on CPU1
mI (625) main_task: Started on CPU0
I (635) main_task: Calling app_main()
I (655) BTDM_INIT: BT controller compile version [946b762]
I (655) BTDM_INIT: Bluetooth MAC: b0:a7:32:1c:b2:ce
I (655) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (995) esp32_nimble::ble_device: BLE Host Task Started
I (1035) esp32_nimble::ble_device: Device Address: B0:A7:32:1C:B2:CE
primary service
           uuid 0x1800
         handle 1
     end_handle 5
characteristic
           uuid 0x2a00
     def_handle 2
     val_handle 3
   min_key_size 0
          flags [READ]
characteristic
           uuid 0x2a01
     def_handle 4
     val_handle 5
   min_key_size 0
          flags [READ]
primary service
           uuid 0x1801
         handle 6
     end_handle 9
characteristic
           uuid 0x2a05
     def_handle 7
     val_handle 8
   min_key_size 0
          flags [INDICATE]
ccc descriptor
           uuid 0x2902
         handle 9
   min_key_size 0
          flags [READ|WRITE]
primary service
           uuid 5f6d4f53-5f52-5043-5f53-56435f49445f
         handle 10
     end_handle 10
I (1105) NimBLE: GAP procedure initiated: advertise; 
I (1105) NimBLE: disc_mode=2
I (1105) NimBLE:  adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0
I (1115) NimBLE: 

The last log line makes it feel like a freeze? I have no evidence for that though. The ESP32 is not frozen though, as I can just add a log line in the final loop and it keeps happening.

[FrigoEU]

Update: This problem seems to have been introduced in version 2.0 and is still there in 2.1. Once I downgrade to 1.4, this problem went away!

[jasta]

I can confirm the same over here with more context in #28. These two issues can be merged.

[jasta]

@FrigoEU can you confirm #31 fixed your issue as well and close accordingly? Thanks!

[FrigoEU]

31 does indeed fix my problem as well. Thanks a lot for the work and the great library!