NimBLE encrypted connections panics (IDFGH-10392)

vabatta commented 1 year ago

Answers checklist.

[X] I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
[X] I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
[X] I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

v3.50002.230601

Operating System used.

macOS

How did you build your project?

Other (please specify in More Information)

If you are using Windows, please specify command line type.

None

Development Kit.

T-SIM7080G-S3

Power Supply used.

USB

What is the expected behavior?

When running the default example from https://github.com/espressif/esp-idf/tree/master/examples/bluetooth/nimble/bleprph with encryption enabled on the GATT service (BLE_GATT_CHR_F_READ_ENC) I would expect to work and ask me for a passkey as setup in the example.

What is the actual behavior?

When requesting access to the characteristic encrypted, the device panics and reboot.

Steps to reproduce.

Run the example https://github.com/espressif/esp-idf/tree/master/examples/bluetooth/nimble/bleprph
Connect to the device
Read from the encoded characteristic to have it panic

Debug Logs.

D (445) heap_init: New heap initialised at 0x3fc9d4b8
I (449) heap_init: At 3FC9D4B8 len 0004C258 (304 KiB): DRAM
I (455) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
D (460) heap_init: New heap initialised at 0x3fcf0000
I (465) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
D (470) heap_init: New heap initialised at 0x600fe010
I (475) heap_init: At 600FE010 len 00001FF0 (7 KiB): RTCRAM
D (481) intr_alloc: Connected src 39 to int 2 (cpu 0)
D (486) spi_flash: trying chip: issi
D (489) spi_flash: trying chip: gd
I (492) spi_flash: detected chip: gd
I (495) spi_flash: flash io: dio
D (498) cpu_start: calling init function: 0x42049a1c
D (503) cpu_start: calling init function: 0x4203f1d0
D (508) cpu_start: calling init function: 0x4203e378
D (512) cpu_start: calling init function: 0x420143b4
D (517) cpu_start: calling init function: 0x42012cf4
D (522) cpu_start: calling init function: 0x42015654 on core: 0
D (527) intr_alloc: Connected src 59 to int 3 (cpu 0)
D (532) cpu_start: calling init function: 0x420148b4 on core: 0
I (538) coexist: coexist rom version e7ae62f
D (542) intr_alloc: Connected src 79 to int 9 (cpu 0)
I (546) cpu_start: Starting scheduler on PRO CPU.
D (551) intr_alloc: Connected src 57 to int 12 (cpu 0)
D (551) intr_alloc: Connected src 80 to int 2 (cpu 1)
I (551) cpu_start: Starting scheduler on APP CPU.
D (561) intr_alloc: Connected src 58 to int 3 (cpu 1)
D (561) heap_init: New heap initialised at 0x3fce9710
D (571) intr_alloc: Connected src 52 to int 13 (cpu 0)
I (591) BT_INIT: BT controller compile version [80abacd]
I (591) phy_init: phy_version 540,a5d905b,Oct 20 2022,19:36:11
D (591) phy_init: loading PHY init data from application binary
D (591) nvs: nvs_open_from_partition phy 0
D (601) nvs: nvs_get cal_version 4
D (601) nvs: nvs_get_str_or_blob cal_mac
D (601) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit
D (611) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit
D (611) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit
D (621) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit
D (631) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit
D (631) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit
D (641) nvs: nvs_get_str_or_blob cal_data
D (651) nvs: nvs_close 1
D (651) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit
D (651) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit
D (661) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit
D (671) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit
D (671) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit
D (681) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit
I (721) system_api: Base MAC address is not set
I (721) system_api: read default base MAC address from EFUSE
D (721) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit
D (721) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit
D (731) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit
D (731) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit
D (741) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit
D (751) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit
I (751) BT_INIT: Bluetooth MAC: 34:85:18:6c:72:e6

I (761) BLE: BLE Host Task Started
I (771) NimBLE: GAP procedure initiated: stop advertising.

I (771) NimBLE: GAP procedure initiated: advertise; 
I (771) NimBLE: disc_mode=2
I (771) NimBLE:  adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0
I (781) NimBLE: 

I (791) CUBELOCK: BLE init success
I (12721) BLE: connection established; status=0 
I (12721) BLE: 

I (12891) BLE: Unhandled GAP event: 18

I (12941) BLE: mtu update event; conn_handle=1 cid=4 mtu=256

I (13091) BLE: subscribe event; conn_handle=1 attr_handle=8 reason=1 prevn=0 curn=0 previ=0 curi=1

D (29861) gdma: new group (0) at 0x3fca040c
D (29861) gdma: new pair (0,0) at 0x3fca0450
D (29861) gdma: new tx channel (0,0) at 0x3fca03dc
D (29861) gdma: new rx channel (0,0) at 0x3fca0470

***ERROR*** A stack overflow in task nimble_host has been detected.

Backtrace: 0x40377052:0x3fcb0550 0x4037fad1:0x3fcb0570 0x40382b1a:0x3fcb0590 0x40381973:0x3fcb0610 0x4037fb88:0x3fcb0630 0x4037fb7e:0x4201a908 |<-CORRUPTED

More Information.

I use PlatformIO with esp-idf framework 3.50002.230601 (5.0.2).

SumeetSingh19 commented 1 year ago

Hi @vabatta , I tried to reproduce the issue on IDF master branch with the bleprph example running with blecent and nRF Connect, but I could not see the issue. I have attached success logs for your reference.

To debug your issue further, can you tell me these things:

Which app did you connect with bleprph.
How did you enable encryption for the characteristic?
Did you enable any other settings in menuconfig?
Looking at the logs, it looks like you have made some changes of your own in the app, so if you can send the app you're running we may be able to reproduce at our end.
Also, due to the changes, there may be more tasks and variables and the stack size may be falling short, can you try to run it again but with an increased stack size. You can find the stack size in `idf.py menuconfig > Component Config > Bluetooth > NimBLE Options > NimBLE Host task stack size".

prph-nrfConnect.log prph-with-cent.log

vabatta commented 1 year ago

I'm about to open a git repository with the code, so you can take a look, because I am having weird behaviors. I've been switching between the NimBLE peripheral example and the BlueDroid GATT security server, and now can't run any of those.

The NimBLE example, no more custom modification, runs but as soon as I connect, the peer device gets disconnected and the esp32 reports as a reason=531.

The Bluedroid BLE GATT security, no custom modification, I can't connect as above.

While if I use the custom code built from the Bluedroid BLE security example, I am able to connect and pair + bond but get disconnected after a few seconds.

Worth mentioning, I've paired and bonded with the device prior to run the clean examples.

I start to think my device has some issues (despite being new).

So from my side:

I'll now try to setup a native espidf setup to see if PlatformIO introduces any issue.
I'll post the GitHub repos (for both native and PlatformIO)

Any suggestions on anything else I could do, besides the aforementioned points?

vabatta commented 1 year ago

This is the behaviour with native espidf for https://github.com/vabatta/espidf-example-nimble-prph.

The weird behaviour is that before I was able to connect with the devices (my laptop - BlueSee, my phone - nRF Connect) but couldn't get the encryption to work. Now as soon as I connect, I just get disconnected with reason 531 as you see in the logs. What happens in between, is that I switched to the GATT Security Server example with BLE BlueDroid and connected with both my devices (and made a bond, accepting pairing popup). Then switched to this example, and this issue happened making me unable to connect with NimBLE anymore.

The only change in SDK is to enable the debug logs for both NimBLE and the app (Log Option), attached below.

Debug log

``` ESP-ROM:esp32s3-20210327 Build:Mar 27 2021 rst:0x15 (USB_UART_CHIP_RESET),boot:0x28 (SPI_FAST_FLASH_BOOT) Saved PC:0x42008292 0x42008292: uart_tx_char at /Users/vabatta/.espressif/esp-idf/components/vfs/vfs_uart.c:156 (discriminator 1) SPIWP:0xee mode:DIO, clock div:1 load:0x3fce3810,len:0x165c load:0x403c9700,len:0xbe0 load:0x403cc700,len:0x2d9c entry 0x403c9900 I (24) boot: ESP-IDF v5.0.2-dirty 2nd stage bootloader I (25) boot: compile time 23:51:14 I (25) boot: chip revision: v0.1 I (27) boot.esp32s3: Boot SPI Speed : 80MHz I (32) boot.esp32s3: SPI Mode : DIO I (37) boot.esp32s3: SPI Flash Size : 2MB I (41) boot: Enabling RNG early entropy source... I (47) boot: Partition Table: I (50) boot: ## Label Usage Type ST Offset Length I (58) boot: 0 nvs WiFi data 01 02 00009000 00006000 I (65) boot: 1 phy_init RF data 01 01 0000f000 00001000 I (72) boot: 2 factory factory app 00 00 00010000 00100000 I (80) boot: End of partition table I (84) esp_image: segment 0: paddr=00010020 vaddr=3c060020 size=1b100h (110848) map I (112) esp_image: segment 1: paddr=0002b128 vaddr=3fc98300 size=038d0h ( 14544) load I (116) esp_image: segment 2: paddr=0002ea00 vaddr=40374000 size=01618h ( 5656) load I (120) esp_image: segment 3: paddr=00030020 vaddr=42000020 size=56510h (353552) map I (190) esp_image: segment 4: paddr=00086538 vaddr=40375618 size=12c44h ( 76868) load I (216) boot: Loaded app from partition at offset 0x10000 I (216) boot: Disabling RNG early entropy source... D (227) flash HPM: HPM with dummy, status is 3 I (227) cpu_start: Pro cpu up. I (228) cpu_start: Starting app cpu, entry point is 0x4037555c 0x4037555c: call_start_cpu1 at /Users/vabatta/.espressif/esp-idf/components/esp_system/port/cpu_start.c:141 (m23I 1() 0)e fucpseu:_ sInta rEtFU:SE _BApLpK 1c_p_DAuTA 4u_pR.E[ 0ims used 7 bits starting with 20 bit D (238) efuse: In EFUSE_BLK1__DATA5_REG is used 8 bits starting with 3 bit D (245) efuse: In EFUSE_BLK1__DATA5_REG is used 5 bits starting with 11 bit D (252) efuse: In EFUSE_BLK1__DATA4_REG is used 7 bits starting with 13 bit D (259) efuse: In EFUSE_BLK1__DATA4_REG is used 7 bits starting with 20 bit D (266) efuse: In EFUSE_BLK1__DATA4_REG is used 5 bits starting with 27 bit D (273) efuse: In EFUSE_BLK1__DATA5_REG is used 3 bits starting with 0 bit D (280) efuse: In EFUSE_BLK1__DATA5_REG is used 8 bits starting with 3 bit D (287) efuse: In EFUSE_BLK1__DATA4_REG is used 7 bits starting with 13 bit D (294) efuse: In EFUSE_BLK1__DATA4_REG is used 7 bits starting with 20 bit D (301) efuse: In EFUSE_BLK1__DATA4_REG is used 5 bits starting with 27 bit D (308) efuse: In EFUSE_BLK1__DATA5_REG is used 3 bits starting with 0 bit D (315) efuse: In EFUSE_BLK1__DATA5_REG is used 8 bits starting with 3 bit D (330) clk: RTC_SLOW_CLK calibration value: 3926490 I (339) cpu_start: Pro cpu start user code I (339) cpu_start: cpu freq: 160000000 Hz I (339) cpu_start: Application information: I (342) cpu_start: Project name: bleprph I (347) cpu_start: App version: 1 I (352) cpu_start: Compile time: Jun 14 2023 23:51:11 I (358) cpu_start: ELF file SHA256: 5f5a94093d47486e... I (364) cpu_start: ESP-IDF: v5.0.2-dirty I (369) cpu_start: Min chip rev: v0.0 I (374) cpu_start: Max chip rev: v0.99 I (379) cpu_start: Chip rev: v0.1 D (383) memory_layout: Checking 5 reserved memory ranges: D (389) memory_layout: Reserved memory range 0x3fc84000 - 0x3fc98300 D (395) memory_layout: Reserved memory range 0x3fc98300 - 0x3fc9e610 D (402) memory_layout: Reserved memory range 0x3fceee34 - 0x3fcf0000 D (408) memory_layout: Reserved memory range 0x40374000 - 0x40388300 0x40374000: _WindowOverflow4 at /Users/vabatta/.espressif/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1743 D (414) memory_layout: Reserved memory range 0x600fe000 - 0x600fe010 D (421) memory_layout: Building list of available memory regions: D (427) memory_layout: Available memory region 0x3fc9e610 - 0x3fca0000 D (434) memory_layout: Available memory region 0x3fca0000 - 0x3fcb0000 D (440) memory_layout: Available memory region 0x3fcb0000 - 0x3fcc0000 D (447) memory_layout: Available memory region 0x3fcc0000 - 0x3fcd0000 D (453) memory_layout: Available memory region 0x3fcd0000 - 0x3fce0000 D (460) memory_layout: Available memory region 0x3fce0000 - 0x3fce9710 D (467) memory_layout: Available memory region 0x3fce9710 - 0x3fceee34 D (473) memory_layout: Available memory region 0x3fcf0000 - 0x3fcf8000 D (480) memory_layout: Available memory region 0x600fe010 - 0x60100000 I (486) heap_init: Initializing. RAM available for dynamic allocation: D (494) heap_init: New heap initialised at 0x3fc9e610 I (499) heap_init: At 3FC9E610 len 0004B100 (300 KiB): DRAM I (505) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM D (512) heap_init: New heap initialised at 0x3fcf0000 I (517) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM D (523) heap_init: New heap initialised at 0x600fe010 I (528) heap_init: At 600FE010 len 00001FF0 (7 KiB): RTCRAM D (535) intr_alloc: Connected src 39 to int 2 (cpu 0) D (540) spi_flash: trying chip: issi D (543) spi_flash: trying chip: gd I (547) spi_flash: detected chip: gd I (551) spi_flash: flash io: dio W (555) spi_flash: Detected size(16384k) larger than the size in the binary image header(2048k). Using the size in the binary image header. D (568) cpu_start: calling init function: 0x420379e0 0x420379e0: _GLOBAL__sub_I__ZN9__gnu_cxx9__freeresEv at eh_alloc.cc:? D (573) cpu_start: calling init function: 0x420374fc 0x420374fc: _GLOBAL__sub_I___cxa_get_globals_fast at eh_globals.cc:? D (578) cpu_start: calling init function: 0x42027d2c 0x42027d2c: esp_ipc_init at /Users/vabatta/.espressif/esp-idf/components/esp_system/esp_ipc.c:115 D (583) cpu_start: calling init function: 0x42003088 0x42003088: esp_reset_reason_init at /Users/vabatta/.espressif/esp-idf/components/esp_system/port/soc/esp32s3/reset_reason.c:67 D (588) cpu_start: calling init function: 0x42002054 0x42002054: esp_init_app_elf_sha256 at /Users/vabatta/.espressif/esp-idf/components/esp_app_format/esp_app_desc.c:69 D (593) cpu_start: calling init function: 0x420073b4 on core: 0 0x420073b4: __esp_system_init_fn_esp_timer_startup_init at /Users/vabatta/.espressif/esp-idf/components/esp_timer/src/esp_timer.c:509 D (599) intr_alloc: Connected src 59 to int 3 (cpu 0) D (604) cpu_start: calling init function: 0x42002d44 on core: 0 0x42002d44: __esp_system_init_fn_init_components0 at /Users/vabatta/.espressif/esp-idf/components/esp_system/startup.c:484 I (611) coexist: coexist rom version e7ae62f D (616) intr_alloc: Connected src 79 to int 9 (cpu 0) I (620) cpu_start: Starting scheduler on PRO CPU. D (626) intr_alloc: Connected src 57 to int 12 (cpu 0) D (626) intr_alloc: Connected src 80 to int 2 (cpu 1) I (636) cpu_start: Starting scheduler on APP CPU. D (636) intr_alloc: Connected src 58 to int 3 (cpu 1) D (646) heap_init: New heap initialised at 0x3fce9710 D (646) intr_alloc: Connected src 52 to int 13 (cpu 0) I (666) BT_INIT: BT controller compile version [80abacd] I (666) phy_init: phy_version 540,a5d905b,Oct 20 2022,19:36:11 D (666) phy_init: loading PHY init data from application binary D (666) nvs: nvs_open_from_partition phy 0 D (676) nvs: nvs_get cal_version 4 D (676) nvs: nvs_get_str_or_blob cal_mac D (686) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit D (686) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit D (696) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit D (706) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit D (706) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit D (716) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit D (726) nvs: nvs_get_str_or_blob cal_data D (736) nvs: nvs_close 1 D (736) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit D (736) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit D (746) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit D (756) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit D (756) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit D (766) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit I (806) system_api: Base MAC address is not set I (806) system_api: read default base MAC address from EFUSE D (806) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit D (806) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit D (816) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit D (826) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit D (826) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit D (836) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit I (846) BT_INIT: Bluetooth MAC: 34:85:18:6c:72:e6 I (856) NimBLE_BLE_PRPH: BLE Host Task Started D (856) NimBLE: registered service 0x1800 with handle=1 D (856) NimBLE: registering characteristic 0x2a00 with def_handle=2 val_handle=3 D (866) NimBLE: registering characteristic 0x2a01 with def_handle=4 val_handle=5 D (876) NimBLE: registered service 0x1801 with handle=6 D (876) NimBLE: registering characteristic 0x2a05 with def_handle=7 val_handle=8 D (886) NimBLE: registered service 0x1811 with handle=10 D (896) NimBLE: registering characteristic 0x2a47 with def_handle=11 val_handle=12 D (906) NimBLE: registering characteristic 0x2a46 with def_handle=13 val_handle=14 D (906) NimBLE: registering characteristic 0x2a48 with def_handle=16 val_handle=17 D (916) NimBLE: registering characteristic 0x2a45 with def_handle=18 val_handle=19 D (926) NimBLE: registering characteristic 0x2a44 with def_handle=21 val_handle=22 D (936) NimBLE: registered service 59462f12-9543-9999-12c8-58b459a2712d with handle=23 D (946) NimBLE: registering characteristic 33333333-2222-2222-1111-111100000000 with def_handle=24 val_handle=25 D (956) NimBLE: registering descriptor 34343434-2323-2323-1212-121201010101 with handle=27 D (956) NimBLE: ble_hs_hci_cmd_send: ogf=0x03 ocf=0x0003 len=0 D (966) NimBLE: 0x03 D (966) NimBLE: 0x0c D (966) NimBLE: 0x00 D (976) NimBLE: D (976) NimBLE: ble_hs_hci_cmd_send: ogf=0x04 ocf=0x0001 len=0 D (986) NimBLE: 0x01 D (986) NimBLE: 0x10 D (986) NimBLE: 0x00 D (986) NimBLE: D (986) NimBLE: ble_hs_hci_cmd_send: ogf=0x04 ocf=0x0003 len=0 D (996) NimBLE: 0x03 D (996) NimBLE: 0x10 D (1006) NimBLE: 0x00 D (1006) NimBLE: D (1006) NimBLE: ble_hs_hci_cmd_send: ogf=0x03 ocf=0x0001 len=8 D (1016) NimBLE: 0x01 D (1016) NimBLE: 0x0c D (1016) NimBLE: 0x08 D (1016) NimBLE: 0x90 D (1026) NimBLE: 0x80 D (1026) NimBLE: 0x00 D (1026) NimBLE: 0x02 D (1026) NimBLE: 0x00 D (1036) NimBLE: 0x80 D (1036) NimBLE: 0x00 D (1036) NimBLE: 0x20 D (1036) NimBLE: D (1036) NimBLE: ble_hs_hci_cmd_send: ogf=0x03 ocf=0x0063 len=8 D (1046) NimBLE: 0x63 D (1046) NimBLE: 0x0c D (1056) NimBLE: 0x08 D (1056) NimBLE: 0x00 D (1056) NimBLE: 0x00 D (1056) NimBLE: 0x80 D (1066) NimBLE: 0x00 D (1066) NimBLE: 0x00 D (1066) NimBLE: 0x00 D (1066) NimBLE: 0x00 D (1076) NimBLE: 0x00 D (1076) NimBLE: D (1076) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0001 len=8 D (1086) NimBLE: 0x01 D (1086) NimBLE: 0x20 D (1086) NimBLE: 0x08 D (1086) NimBLE: 0x7f D (1096) NimBLE: 0xfe D (1096) NimBLE: 0x0f D (1096) NimBLE: 0x00 D (1096) NimBLE: 0x00 D (1106) NimBLE: 0x00 D (1106) NimBLE: 0x00 D (1106) NimBLE: 0x00 D (1106) NimBLE: D (1116) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0002 len=0 D (1116) NimBLE: 0x02 D (1116) NimBLE: 0x20 D (1126) NimBLE: 0x00 D (1126) NimBLE: D (1126) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0003 len=0 D (1136) NimBLE: 0x03 D (1136) NimBLE: 0x20 D (1136) NimBLE: 0x00 D (1136) NimBLE: D (1146) NimBLE: ble_hs_hci_cmd_send: ogf=0x04 ocf=0x0009 len=0 D (1146) NimBLE: 0x09 D (1146) NimBLE: 0x10 D (1156) NimBLE: 0x00 D (1156) NimBLE: D (1156) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x002d len=1 D (1166) NimBLE: 0x2d D (1166) NimBLE: 0x20 D (1166) NimBLE: 0x01 D (1176) NimBLE: 0x00 D (1176) NimBLE: D (1176) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0029 len=0 D (1186) NimBLE: 0x29 D (1186) NimBLE: 0x20 D (1186) NimBLE: 0x00 D (1186) NimBLE: D (1196) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x002d len=1 D (1196) NimBLE: 0x2d D (1196) NimBLE: 0x20 D (1206) NimBLE: 0x01 D (1206) NimBLE: 0x01 D (1206) NimBLE: I (1206) NimBLE: GAP procedure initiated: stop advertising. D (1216) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x000a len=1 D (1226) NimBLE: 0x0a D (1226) NimBLE: 0x20 D (1226) NimBLE: 0x01 D (1226) NimBLE: 0x00 D (1236) NimBLE: D (1236) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0027 len=39 D (1236) NimBLE: 0x27 D (1246) NimBLE: 0x20 D (1246) NimBLE: 0x27 D (1246) NimBLE: 0x00 D (1246) NimBLE: 0x00 D (1256) NimBLE: 0x00 D (1256) NimBLE: 0x00 D (1256) NimBLE: 0x00 D (1256) NimBLE: 0x00 D (1266) NimBLE: 0x00 D (1266) NimBLE: 0x00 D (1266) NimBLE: 0x00 D (1266) NimBLE: 0x00 D (1276) NimBLE: 0x00 D (1276) NimBLE: 0x00 D (1276) NimBLE: 0x00 D (1276) NimBLE: 0x00 D (1286) NimBLE: 0x00 D (1286) NimBLE: 0x00 D (1286) NimBLE: 0x00 D (1286) NimBLE: 0x00 D (1296) NimBLE: 0x00 D (1296) NimBLE: 0x00 D (1296) NimBLE: 0x00 D (1296) NimBLE: 0x00 D (1306) NimBLE: 0x00 D (1306) NimBLE: 0xef D (1306) NimBLE: 0x8d D (1306) NimBLE: 0xe2 D (1306) NimBLE: 0x16 D (1316) NimBLE: 0x4f D (1316) NimBLE: 0xec D (1316) NimBLE: 0x43 D (1316) NimBLE: 0x0d D (1326) NimBLE: 0xbf D (1326) NimBLE: 0x5b D (1326) NimBLE: 0xdd D (1326) NimBLE: 0x34 D (1336) NimBLE: 0xc0 D (1336) NimBLE: 0x53 D (1336) NimBLE: 0x1e D (1336) NimBLE: 0xb8 D (1346) NimBLE: D (1346) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x004e len=8 D (1346) NimBLE: 0x4e D (1356) NimBLE: 0x20 D (1356) NimBLE: 0x08 D (1356) NimBLE: 0x00 D (1356) NimBLE: 0x00 D (1366) NimBLE: 0x00 D (1366) NimBLE: 0x00 D (1366) NimBLE: 0x00 D (1366) NimBLE: 0x00 D (1376) NimBLE: 0x00 D (1376) NimBLE: 0x01 D (1376) NimBLE: D (1376) NimBLE: looking up peer sec; D (1386) NimBLE: I (1386) NimBLE: Device Address: I (1386) NimBLE: 34:85:18:6c:72:e6 I (1396) NimBLE: D (1396) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0007 len=0 D (1406) NimBLE: 0x07 D (1406) NimBLE: 0x20 D (1406) NimBLE: 0x00 D (1406) NimBLE: D (1416) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0008 len=32 D (1416) NimBLE: 0x08 D (1416) NimBLE: 0x20 D (1426) NimBLE: 0x20 D (1426) NimBLE: 0x1a D (1426) NimBLE: 0x02 D (1426) NimBLE: 0x01 D (1436) NimBLE: 0x06 D (1436) NimBLE: 0x03 D (1436) NimBLE: 0x03 D (1436) NimBLE: 0x11 D (1446) NimBLE: 0x18 D (1446) NimBLE: 0x0f D (1446) NimBLE: 0x09 D (1446) NimBLE: 0x6e D (1456) NimBLE: 0x69 D (1456) NimBLE: 0x6d D (1456) NimBLE: 0x62 D (1456) NimBLE: 0x6c D (1466) NimBLE: 0x65 D (1466) NimBLE: 0x2d D (1466) NimBLE: 0x62 D (1466) NimBLE: 0x6c D (1476) NimBLE: 0x65 D (1476) NimBLE: 0x70 D (1476) NimBLE: 0x72 D (1476) NimBLE: 0x70 D (1486) NimBLE: 0x68 D (1486) NimBLE: 0x02 D (1486) NimBLE: 0x0a D (1486) NimBLE: 0x09 D (1496) NimBLE: 0x3f D (1496) NimBLE: 0xb6 D (1496) NimBLE: 0xa5 D (1496) NimBLE: 0xc9 D (1496) NimBLE: 0x3f D (1506) NimBLE: I (1506) NimBLE: GAP procedure initiated: advertise; I (1516) NimBLE: disc_mode=2 I (1516) NimBLE: adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0 I (1526) NimBLE: D (1526) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0006 len=15 D (1536) NimBLE: 0x06 D (1536) NimBLE: 0x20 D (1536) NimBLE: 0x0f D (1546) NimBLE: 0x30 D (1546) NimBLE: 0x00 D (1546) NimBLE: 0x60 D (1546) NimBLE: 0x00 D (1546) NimBLE: 0x00 D (1556) NimBLE: 0x00 D (1556) NimBLE: 0x00 D (1556) NimBLE: 0x00 D (1556) NimBLE: 0x00 D (1566) NimBLE: 0x00 D (1566) NimBLE: 0x00 D (1566) NimBLE: 0x00 D (1566) NimBLE: 0x00 D (1576) NimBLE: 0x07 D (1576) NimBLE: 0x00 D (1576) NimBLE: D (1576) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x000a len=1 D (1586) NimBLE: 0x0a D (1586) NimBLE: 0x20 D (1586) NimBLE: 0x01 D (1596) NimBLE: 0x01 D (1596) NimBLE: I (1596) uart: queue free spaces: 8 D (1606) intr_alloc: Connected src 27 to int 4 (cpu 1) I (9906) NimBLE: connection established; status=0 I (9906) NimBLE: handle=1 our_ota_addr_type=0 our_ota_addr= I (9906) NimBLE: 34:85:18:6c:72:e6 I (9906) NimBLE: our_id_addr_type=0 our_id_addr= I (9916) NimBLE: 34:85:18:6c:72:e6 I (9916) NimBLE: peer_ota_addr_type=0 peer_ota_addr= I (9926) NimBLE: f0:2f:4b:08:ec:2b I (9926) NimBLE: peer_id_addr_type=0 peer_id_addr= I (9936) NimBLE: f0:2f:4b:08:ec:2b I (9936) NimBLE: conn_itvl=9 conn_latency=0 supervision_timeout=36 encrypted=0 authenticated=0 bonded=0 I (9946) NimBLE: D (9946) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0016 len=2 D (9956) NimBLE: 0x16 D (9956) NimBLE: 0x20 D (9956) NimBLE: 0x02 D (9966) NimBLE: 0x01 D (9966) NimBLE: 0x00 D (9966) NimBLE: D (9966) NimBLE: looking up our sec; D (9976) NimBLE: peer_addr_type=0 peer_addr= D (9976) NimBLE: 0x2b D (9976) NimBLE: 0xec D (9986) NimBLE: 0x08 D (9986) NimBLE: 0x4b D (9986) NimBLE: 0x2f D (9986) NimBLE: 0xf0 D (9996) NimBLE: D (9996) NimBLE: ediv=0x00 rand=0x0 D (9996) NimBLE: D (9996) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x001b len=2 D (10006) NimBLE: 0x1b D (10006) NimBLE: 0x20 D (10006) NimBLE: 0x02 D (10016) NimBLE: 0x01 D (10016) NimBLE: 0x00 D (10016) NimBLE: I (10036) NimBLE: disconnect; reason=531 I (10036) NimBLE: handle=1 our_ota_addr_type=0 our_ota_addr= I (10036) NimBLE: 34:85:18:6c:72:e6 I (10046) NimBLE: our_id_addr_type=0 our_id_addr= I (10046) NimBLE: 34:85:18:6c:72:e6 I (10056) NimBLE: peer_ota_addr_type=0 peer_ota_addr= I (10056) NimBLE: f0:2f:4b:08:ec:2b I (10066) NimBLE: peer_id_addr_type=0 peer_id_addr= I (10066) NimBLE: f0:2f:4b:08:ec:2b I (10076) NimBLE: conn_itvl=9 conn_latency=0 supervision_timeout=36 encrypted=0 authenticated=0 bonded=0 I (10086) NimBLE: D (10086) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0007 len=0 D (10096) NimBLE: 0x07 D (10096) NimBLE: 0x20 D (10096) NimBLE: 0x00 D (10096) NimBLE: D (10106) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0008 len=32 D (10106) NimBLE: 0x08 D (10106) NimBLE: 0x20 D (10116) NimBLE: 0x20 D (10116) NimBLE: 0x1a D (10116) NimBLE: 0x02 D (10116) NimBLE: 0x01 D (10126) NimBLE: 0x06 D (10126) NimBLE: 0x03 D (10126) NimBLE: 0x03 D (10126) NimBLE: 0x11 D (10136) NimBLE: 0x18 D (10136) NimBLE: 0x0f D (10136) NimBLE: 0x09 D (10136) NimBLE: 0x6e D (10146) NimBLE: 0x69 D (10146) NimBLE: 0x6d D (10146) NimBLE: 0x62 D (10146) NimBLE: 0x6c D (10156) NimBLE: 0x65 D (10156) NimBLE: 0x2d D (10156) NimBLE: 0x62 D (10156) NimBLE: 0x6c D (10166) NimBLE: 0x65 D (10166) NimBLE: 0x70 D (10166) NimBLE: 0x72 D (10166) NimBLE: 0x70 D (10176) NimBLE: 0x68 D (10176) NimBLE: 0x02 D (10176) NimBLE: 0x0a D (10176) NimBLE: 0x09 D (10186) NimBLE: 0x3f D (10186) NimBLE: 0xb6 D (10186) NimBLE: 0xa5 D (10186) NimBLE: 0xc9 D (10196) NimBLE: 0x3f D (10196) NimBLE: I (10196) NimBLE: GAP procedure initiated: advertise; I (10206) NimBLE: disc_mode=2 I (10206) NimBLE: adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0 I (10216) NimBLE: D (10216) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0006 len=15 D (10226) NimBLE: 0x06 D (10226) NimBLE: 0x20 D (10236) NimBLE: 0x0f D (10236) NimBLE: 0x30 D (10236) NimBLE: 0x00 D (10236) NimBLE: 0x60 D (10246) NimBLE: 0x00 D (10246) NimBLE: 0x00 D (10246) NimBLE: 0x00 D (10246) NimBLE: 0x00 D (10256) NimBLE: 0x00 D (10256) NimBLE: 0x00 D (10256) NimBLE: 0x00 D (10256) NimBLE: 0x00 D (10266) NimBLE: 0x00 D (10266) NimBLE: 0x00 D (10266) NimBLE: 0x07 D (10266) NimBLE: 0x00 D (10276) NimBLE: D (10276) NimBLE: ble_hs_hci_cmd_send: ogf=0x08 ocf=0x000a len=1 D (10276) NimBLE: 0x0a D (10286) NimBLE: 0x20 D (10286) NimBLE: 0x01 D (10286) NimBLE: 0x01 D (10286) NimBLE: ```

vabatta commented 1 year ago

This is the behaviour with the native espidf for https://github.com/vabatta/espidf-example-ble50-security.

Same as for NimBLE, as soon as I connect it gets disconnected.

The only change in SDK is to enable the debug logs for each BlueDroid component and the app.

Debug Log (boot example)

``` ESP-ROM:esp32s3-20210327 Build:Mar 27 2021 rst:0x15 (USB_UART_CHIP_RESET),boot:0x28 (SPI_FAST_FLASH_BOOT) Saved PC:0x420096fb 0x420096fb: uart_ll_get_txfifo_len at /Users/vabatta/.espressif/esp-idf/components/hal/esp32s3/include/hal/uart_ll.h:314 (discriminator 1) (inlined by) uart_tx_char at /Users/vabatta/.espressif/esp-idf/components/vfs/vfs_uart.c:156 (discriminator 1) SPIWP:0xee mode:DIO, clock div:1 load:0x3fce3810,len:0x165c load:0x403c9700,len:0xbe0 load:0x403cc700,len:0x2d9c entry 0x403c9900 I (24) boot: ESP-IDF v5.0.2-dirty 2nd stage bootloader I (25) boot: compile time 00:11:43 I (25) boot: chip revision: v0.1 I (27) boot.esp32s3: Boot SPI Speed : 80MHz I (32) boot.esp32s3: SPI Mode : DIO I (37) boot.esp32s3: SPI Flash Size : 2MB I (41) boot: Enabling RNG early entropy source... I (47) boot: Partition Table: I (50) boot: ## Label Usage Type ST Offset Length I (58) boot: 0 nvs WiFi data 01 02 00009000 00006000 I (65) boot: 1 phy_init RF data 01 01 0000f000 00001000 I (72) boot: 2 factory factory app 00 00 00010000 00100000 I (80) boot: End of partition table I (84) esp_image: segment 0: paddr=00010020 vaddr=3c090020 size=321a0h (205216) map I (129) esp_image: segment 1: paddr=000421c8 vaddr=3fc96500 size=036f8h ( 14072) load I (133) esp_image: segment 2: paddr=000458c8 vaddr=40374000 size=0a750h ( 42832) load I (145) esp_image: segment 3: paddr=00050020 vaddr=42000020 size=892f8h (561912) map I (246) esp_image: segment 4: paddr=000d9320 vaddr=4037e750 size=07d10h ( 32016) load I (261) boot: Loaded app from partition at offset 0x10000 I (261) boot: Disabling RNG early entropy source... D (272) flash HPM: HPM with dummy, status is 3 I (273) cpu_start: Pro cpu up. I (273) cpu_start: Starting app cpu, entry point is 0x4037534c 0x4037534c: call_start_cpu1 at /Users/vabatta/.espressif/esp-idf/components/esp_system/port/cpu_start.c:141 2m(I27 (6) 0)ef ucpsue_:s tIanr EFtU: SAE_BpLKp1 c_p_DAuTA 4u_Rp.E[ is0 umse d 7 bits starting with 20 bit D (283) efuse: In EFUSE_BLK1__DATA5_REG is used 8 bits starting with 3 bit D (290) efuse: In EFUSE_BLK1__DATA5_REG is used 5 bits starting with 11 bit D (297) efuse: In EFUSE_BLK1__DATA4_REG is used 7 bits starting with 13 bit D (304) efuse: In EFUSE_BLK1__DATA4_REG is used 7 bits starting with 20 bit D (311) efuse: In EFUSE_BLK1__DATA4_REG is used 5 bits starting with 27 bit D (319) efuse: In EFUSE_BLK1__DATA5_REG is used 3 bits starting with 0 bit D (325) efuse: In EFUSE_BLK1__DATA5_REG is used 8 bits starting with 3 bit D (332) efuse: In EFUSE_BLK1__DATA4_REG is used 7 bits starting with 13 bit D (339) efuse: In EFUSE_BLK1__DATA4_REG is used 7 bits starting with 20 bit D (346) efuse: In EFUSE_BLK1__DATA4_REG is used 5 bits starting with 27 bit D (353) efuse: In EFUSE_BLK1__DATA5_REG is used 3 bits starting with 0 bit D (360) efuse: In EFUSE_BLK1__DATA5_REG is used 8 bits starting with 3 bit D (376) clk: RTC_SLOW_CLK calibration value: 3931584 I (384) cpu_start: Pro cpu start user code I (385) cpu_start: cpu freq: 160000000 Hz I (385) cpu_start: Application information: I (388) cpu_start: Project name: ble50_sec_gatts_demo I (394) cpu_start: App version: 1 I (398) cpu_start: Compile time: Jun 15 2023 00:11:41 I (404) cpu_start: ELF file SHA256: 074f6b0d64f9cb44... I (410) cpu_start: ESP-IDF: v5.0.2-dirty I (415) cpu_start: Min chip rev: v0.0 I (420) cpu_start: Max chip rev: v0.99 I (425) cpu_start: Chip rev: v0.1 D (430) memory_layout: Checking 5 reserved memory ranges: D (435) memory_layout: Reserved memory range 0x3fc84000 - 0x3fc96500 D (442) memory_layout: Reserved memory range 0x3fc96500 - 0x3fc9db70 D (448) memory_layout: Reserved memory range 0x3fceee34 - 0x3fcf0000 D (454) memory_layout: Reserved memory range 0x40374000 - 0x40386500 0x40374000: _WindowOverflow4 at /Users/vabatta/.espressif/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1743 D (461) memory_layout: Reserved memory range 0x600fe000 - 0x600fe010 D (467) memory_layout: Building list of available memory regions: D (473) memory_layout: Available memory region 0x3fc9db70 - 0x3fca0000 D (480) memory_layout: Available memory region 0x3fca0000 - 0x3fcb0000 D (487) memory_layout: Available memory region 0x3fcb0000 - 0x3fcc0000 D (493) memory_layout: Available memory region 0x3fcc0000 - 0x3fcd0000 D (500) memory_layout: Available memory region 0x3fcd0000 - 0x3fce0000 D (506) memory_layout: Available memory region 0x3fce0000 - 0x3fce9710 D (513) memory_layout: Available memory region 0x3fce9710 - 0x3fceee34 D (520) memory_layout: Available memory region 0x3fcf0000 - 0x3fcf8000 D (526) memory_layout: Available memory region 0x600fe010 - 0x60100000 I (533) heap_init: Initializing. RAM available for dynamic allocation: D (540) heap_init: New heap initialised at 0x3fc9db70 I (545) heap_init: At 3FC9DB70 len 0004BBA0 (302 KiB): DRAM I (551) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM D (558) heap_init: New heap initialised at 0x3fcf0000 I (563) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM D (569) heap_init: New heap initialised at 0x600fe010 I (574) heap_init: At 600FE010 len 00001FF0 (7 KiB): RTCRAM D (581) intr_alloc: Connected src 39 to int 2 (cpu 0) D (586) spi_flash: trying chip: issi D (590) spi_flash: trying chip: gd I (593) spi_flash: detected chip: gd I (597) spi_flash: flash io: dio W (601) spi_flash: Detected size(16384k) larger than the size in the binary image header(2048k). Using the size in the binary image header. D (614) cpu_start: calling init function: 0x4206bca8 0x4206bca8: _GLOBAL__sub_I__ZN9__gnu_cxx9__freeresEv at eh_alloc.cc:? D (620) cpu_start: calling init function: 0x4206b7c4 0x4206b7c4: _GLOBAL__sub_I___cxa_get_globals_fast at eh_globals.cc:? D (625) cpu_start: calling init function: 0x42065d04 0x42065d04: esp_ipc_init at /Users/vabatta/.espressif/esp-idf/components/esp_system/esp_ipc.c:115 D (630) cpu_start: calling init function: 0x42004370 0x42004370: esp_reset_reason_init at /Users/vabatta/.espressif/esp-idf/components/esp_system/port/soc/esp32s3/reset_reason.c:67 D (635) cpu_start: calling init function: 0x4200331c 0x4200331c: esp_init_app_elf_sha256 at /Users/vabatta/.espressif/esp-idf/components/esp_app_format/esp_app_desc.c:69 D (640) cpu_start: calling init function: 0x42008828 on core: 0 0x42008828: __esp_system_init_fn_esp_timer_startup_init at /Users/vabatta/.espressif/esp-idf/components/esp_timer/src/esp_timer.c:509 D (646) intr_alloc: Connected src 59 to int 3 (cpu 0) D (651) cpu_start: calling init function: 0x42004018 on core: 0 0x42004018: __esp_system_init_fn_init_components0 at /Users/vabatta/.espressif/esp-idf/components/esp_system/startup.c:484 I (657) coexist: coexist rom version e7ae62f D (662) intr_alloc: Connected src 79 to int 9 (cpu 0) I (667) cpu_start: Starting scheduler on PRO CPU. D (672) intr_alloc: Connected src 57 to int 12 (cpu 0) D (672) intr_alloc: Connected src 80 to int 2 (cpu 1) I (682) cpu_start: Starting scheduler on APP CPU. D (682) intr_alloc: Connected src 58 to int 3 (cpu 1) D (692) heap_init: New heap initialised at 0x3fce9710 D (692) intr_alloc: Connected src 52 to int 13 (cpu 0) I (712) BT_INIT: BT controller compile version [80abacd] I (712) phy_init: phy_version 540,a5d905b,Oct 20 2022,19:36:11 D (712) phy_init: loading PHY init data from application binary D (712) nvs: nvs_open_from_partition phy 0 D (722) nvs: nvs_get cal_version 4 D (722) nvs: nvs_get_str_or_blob cal_mac D (732) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit D (732) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit D (742) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit D (752) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit D (752) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit D (762) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit D (772) nvs: nvs_get_str_or_blob cal_data D (782) nvs: nvs_close 1 D (782) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit D (782) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit D (792) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit D (802) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit D (802) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit D (812) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit I (852) system_api: Base MAC address is not set I (852) system_api: read default base MAC address from EFUSE D (852) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit D (852) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit D (862) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit D (872) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit D (872) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit D (882) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit I (892) BT_INIT: Bluetooth MAC: 34:85:18:6c:72:e6 I (892) SEC_GATTS_DEMO: app_main init bluetooth D (902) BT_BTC: btc_transfer_context msg 0 0 0 0x0 D (902) BT_BTC: btc_thread_handler msg 0 0 0 0x3fcabe64 D (912) BT_BTC: btc_main_call_handler act 0 D (912) BT_APPL: Enable HCI D (922) BT_OSI: alarm_cbs_lookfor_available 0 0x3fc9c3a8 D (922) BT_OSI: alarm_cbs_lookfor_available 1 0x3fc9c3c0 D (932) BT_HCI: btu_free_timer Unable to find expected alarm in hashmap D (932) BT_HCI: btu_free_timer Unable to find expected alarm in hashmap D (942) BT_BTM: btm_acl_init D (942) BT_L2CAP: L2CA_RegisterFixedChannel() CID: 0x0004, 0x3fcafbb0 I (952) BT_BTM: btm_sec_set_security_level : sec: 0x0 I (962) BT_BTM: BTM_SEC_REG[0]: id 50, is_orig 1, psm 0x001f, proto_id 0, chan_id 0 I (972) BT_BTM: : sec: 0x80, service name [] (up to 21 chars saved) I (972) BT_BTM: btm_sec_set_security_level : sec: 0x0 I (982) BT_BTM: BTM_SEC_REG[0]: id 50, is_orig 0, psm 0x001f, proto_id 0, chan_id 0 I (992) BT_BTM: : sec: 0x80, service name [] (up to 21 chars saved) I (1002) BT_GATT: GATT_Register D (1002) BT_GATT: UUID=[0x81818181818181818181818181818181] I (1012) BT_GATT: allocated gatt_if=1 I (1012) BT_GATT: GATT_StartIf gatt_if=1 D (1022) BT_GATT: gatt_find_the_connected_bda start_idx=0 I (1022) BT_GATT: GATTS_CreateService D (1032) BT_GATT: allocate_svc_db_buf allocating extra buffer D (1032) BT_GATT: gatts_init_service_db D (1042) BT_GATT: s_hdl = 1 num_handle = 5 D (1042) BT_GATT: add_service_declaration D (1042) BT_GATT: allocate attr 20 bytes D (1052) BT_GATT: =====> handle = [0x0001] uuid16 = [0x2800] perm=0x01 D (1052) BT_GATT: GATTS_CreateService: handle of service handle1 D (1062) BT_GATT: gatts_add_characteristic perm=0x0 property=0x20 D (1072) BT_GATT: allocate attr 20 bytes D (1072) BT_GATT: =====> handle = [0x0002] uuid16 = [0x2803] perm=0x01 D (1082) BT_GATT: allocate attr 20 bytes D (1082) BT_GATT: =====> handle = [0x0003] uuid16 = [0x2a05] perm=0x00 D (1092) BT_GATT: gatt_profile_db_init: handle of service changed3 D (1102) BT_GATT: gatts_add_char_descr uuid=0x2902 D (1102) BT_GATT: allocate attr 20 bytes D (1102) BT_GATT: =====> handle = [0x0004] uuid16 = [0x2902] perm=0x11 I (1112) BT_GATT: GATTS_StartService D (1122) BT_GATT: total buffer in db [1] D (1122) BT_GATT: allocated i_sreg=0 D (1122) BT_GATT: s_hdl=1 e_hdl=5 type=0x2800 svc_inst=0 sdp_hdl=0x0 D (1132) BT_GATT: gatt_profile_db_init: gatt_if=1 start status0 D (1142) BT_SMP: SMP_Init D (1142) BT_SMP: SMDBG l2c smp_l2cap_if_init D (1142) BT_L2CAP: L2CA_RegisterFixedChannel() CID: 0x0006, 0x3fcafb90 D (1152) BT_BTM: btm_ble_init D (1152) BT_HCI: btu_free_timer Unable to find expected alarm in hashmap D (1162) BT_HCI: btu_free_timer Unable to find expected alarm in hashmap D (1172) BT_HCI: btu_free_timer Unable to find expected alarm in hashmap I (1172) BT_GATT: GATT_Register D (1182) BT_GATT: UUID=[0x82828282828282828282828282828282] I (1182) BT_GATT: allocated gatt_if=2 I (1192) BT_GATT: GATT_StartIf gatt_if=2 D (1192) BT_GATT: gatt_find_the_connected_bda start_idx=0 I (1202) BT_GATT: GATTS_CreateService D (1202) BT_GATT: allocate_svc_db_buf allocating extra buffer D (1212) BT_GATT: gatts_init_service_db D (1212) BT_GATT: s_hdl = 20 num_handle = 9 D (1222) BT_GATT: add_service_declaration D (1222) BT_GATT: allocate attr 20 bytes D (1222) BT_GATT: =====> handle = [0x0014] uuid16 = [0x2800] perm=0x01 D (1232) BT_GAP: gap_attr_db_init service_handle = 20 D (1242) BT_GATT: gatts_add_characteristic perm=0x1 property=0x2 D (1242) BT_GATT: allocate attr 20 bytes D (1252) BT_GATT: =====> handle = [0x0015] uuid16 = [0x2803] perm=0x01 D (1252) BT_GATT: allocate attr 20 bytes D (1262) BT_GATT: =====> handle = [0x0016] uuid16 = [0x2a00] perm=0x01 D (1262) BT_GATT: gatts_add_characteristic perm=0x1 property=0x2 D (1272) BT_GATT: allocate attr 20 bytes D (1282) BT_GATT: =====> handle = [0x0017] uuid16 = [0x2803] perm=0x01 D (1282) BT_GATT: allocate attr 20 bytes D (1292) BT_GATT: =====> handle = [0x0018] uuid16 = [0x2a01] perm=0x01 D (1292) BT_GATT: gatts_add_characteristic perm=0x1 property=0x2 D (1302) BT_GATT: allocate attr 20 bytes D (1302) BT_GATT: allocate_svc_db_buf allocating extra buffer D (1312) BT_GATT: =====> handle = [0x0019] uuid16 = [0x2803] perm=0x01 D (1322) BT_GATT: allocate attr 20 bytes D (1322) BT_GATT: =====> handle = [0x001a] uuid16 = [0x2aa6] perm=0x01 I (1332) BT_GATT: GATTS_StartService D (1332) BT_GATT: total buffer in db [2] D (1342) BT_GATT: allocated i_sreg=1 D (1342) BT_GATT: s_hdl=20 e_hdl=28 type=0x2800 svc_inst=0 sdp_hdl=0x0 D (1352) BT_GAP: GAP App gatt_if: 2 s_hdl = 20 start_status=0 D (1352) nvs: nvs_open_from_partition bt_config.conf 1 D (1362) nvs: nvs_get_str_or_blob bt_cfg_key0 D (1362) nvs: nvs_get_str_or_blob bt_cfg_key0 D (1372) nvs: nvs_close 2 D (1372) nvs: nvs_open_from_partition bt_config.conf 1 D (1372) BT_OSI: section name: Adapter, w_cnt + w_cnt_total = 10 D (1382) BT_OSI: (key, val): (LE_LOCAL_KEY_IRK, 50b177cb484885950b69026565d7c9c2) D (1392) BT_OSI: config_save, w_cnt + w_cnt_total = 62 D (1392) BT_OSI: (key, val): (LE_LOCAL_KEY_IR, dcf44e01e08b9b65dfb9b9ceca0df9a6) D (1402) BT_OSI: config_save, w_cnt + w_cnt_total = 113 D (1412) BT_OSI: (key, val): (LE_LOCAL_KEY_DHK, d566f7c97c2d08bff29206c4149ad8b3) D (1412) BT_OSI: config_save, w_cnt + w_cnt_total = 165 D (1422) BT_OSI: (key, val): (LE_LOCAL_KEY_ER, 72beaf7001e686dea8afa249eaab507a) D (1432) BT_OSI: config_save, w_cnt + w_cnt_total = 216 D (1432) nvs: nvs_set_blob bt_cfg_key0 216 D (1442) nvs: nvs_close 3 D (1442) BT_BTC: btc_dm_load_ble_local_keys BLE ER key loaded D (1442) BT_BTC: btc_dm_load_ble_local_keys BLE ID keys loaded D (1452) BT_BTC: btc_transfer_context msg 0 0 2 0x0 D (1462) BT_BTC: btc_thread_handler msg 0 0 2 0x3fcabe64 D (1462) BT_BTC: btc_main_call_handler act 2 D (1472) BT_APPL: BTA got event 0x100 D (1472) BT_APPL: bta_dm_sm_execute event:0x0 D (1472) BT_APPL: BTA got event 0x0 D (1482) BT_APPL: bta_sys_sm_execute state:0, event:0x0 D (1482) BT_APPL: bta_sys_hw_api_enable for 0, active modules 0x0001 D (1492) BT_APPL: BTA got event 0x1 D (1492) BT_APPL: bta_sys_sm_execute state:1, event:0x1 D (1502) BT_APPL: bta_sys_hw_evt_enabled for 0 D (1502) BT_BTM: btm_acl_device_down D (1512) BT_HCI: Receive packet event_code=0xe D (1512) BT_HCI: Receive packet event_code=0xe D (1522) BT_HCI: Receive packet event_code=0xe D (1522) BT_HCI: Receive packet event_code=0xe D (1532) BT_HCI: Receive packet event_code=0xe D (1532) BT_HCI: Receive packet event_code=0xe D (1542) BT_HCI: Receive packet event_code=0xe D (1542) BT_HCI: Receive packet event_code=0xe D (1552) BT_HCI: Receive packet event_code=0xe D (1552) BT_HCI: Receive packet event_code=0xe D (1552) BT_HCI: Receive packet event_code=0xe D (1562) BT_HCI: Receive packet event_code=0xe D (1562) BT_HCI: Receive packet event_code=0xe D (1572) BT_HCI: Receive packet event_code=0xe D (1572) BT_HCI: Receive packet event_code=0xe D (1582) BT_HCI: Receive packet event_code=0xe D (1582) BT_BTM: BTM Register For VSEvents is successfully D (1592) BT_BTM: btm_ble_resolving_list_init max_irk_list_sz = 10 D (1592) BT_HCI: HCI Enqueue Comamnd opcode=0x2029 D (1602) BT_HCI: Receive packet event_code=0xe D (1602) BT_HCI: btu_hcif_command_complete_evt D (1612) BT_HCI: HCI Enqueue Comamnd opcode=0x202e D (1612) BT_HCI: Receive packet event_code=0xe D (1622) BT_HCI: btu_hcif_command_complete_evt D (1622) BT_BTM: btm_ble_white_list_init white_list_size = 12 D (1632) BT_L2CAP: num_lm_ble_bufs = 12 D (1632) BT_BTM: btm_decode_ext_features_page page: 0 D (1642) BT_BTM: Local supported ACL packet types: 0x331e D (1642) BT_BTM: Local supported SCO packet types: 0x0000 D (1652) BT_BTM: btm_sec_dev_reset sec mode: 2 I (1652) BT_BTM: BTM_SetPageScanType I (1662) BT_BTM: BTM_SetInquiryScanType D (1662) BT_APPL: bta_sys_hw_btm_cback was called with parameter: 0 D (1672) BT_BTM: btm_ble_clear_resolving_list_complete status=0 D (1672) BT_BTM: btm_ble_clear_resolving_list_complete resolving_list_avail_size=10 D (1682) BT_APPL: BTA got event 0x2 D (1692) BT_APPL: bta_sys_sm_execute state:1, event:0x2 D (1692) BT_APPL: bta_sys_hw_evt_stack_enabled!notify the callers D (1702) BT_APPL: bta_dm_sys_hw_cback with event: 1 D (1702) BT_APPL: bta_sys_free_timer expected alarm was not in bta alarm hash map. D (1712) BT_BTC: btc_dm_get_ble_local_keys *p_key_mask=0x03 D (1722) BT_BTM: BTM_BleLoadLocalKeys D (1722) BT_BTM: BTM_BleLoadLocalKeys D (1722) BT_BTM: BTM_SecRegister application registered D (1732) BT_BTM: BTM_SecRegister p_cb_info->p_le_callback == 0x0x420521b4 0x420521b4: bta_dm_ble_smp_cback at /Users/vabatta/.espressif/esp-idf/components/bt/host/bluedroid/bta/dm/bta_dm_act.c:4650 D (1742) BT_BTM: BTM_SecRegister SMP_Register( btm_proc_smp_cback ) D (1742) BT_SMP: SMP_Register state=0 D (1752) BT_HCI: HCI Enqueue Comamnd opcode=0x2027 D (1752) BT_HCI: Receive packet event_code=0xe D (1762) BT_HCI: btu_hcif_command_complete_evt D (1762) BT_BTM: BTM_SecRegister btm_cb.api.p_le_callback = 0x0x420521b4 0x420521b4: bta_dm_ble_smp_cback at /Users/vabatta/.espressif/esp-idf/components/bt/host/bluedroid/bta/dm/bta_dm_act.c:4650 D (1772) BT_BTM: BTM_SecRegister application registered D (1772) BT_BTM: BTM_SetDefaultLinkSuperTout D (1782) BT_BTM: BTM_RegBusyLevelNotif D (1782) BT_BTM: BTM_RegAclLinkStatNotif D (1792) BT_HCI: HCI Enqueue Comamnd opcode=0xc14 D (1792) BT_HCI: Receive packet event_code=0xe D (1802) BT_HCI: btu_hcif_command_complete_evt D (1802) BT_OSI: alarm_cbs_lookfor_available 2 0x3fc9c3d8 D (1812) BT_OSI: osi_alarm_cancel failed to stop timer, err 0x103 D (1812) BT_BTM: btm_ble_add_resolving_list_entry_complete status = 0 D (1822) BT_BTM: no pending resolving list operation D (1822) BT_BTC: btc_transfer_context msg 1 8 0 0x3fcafa60 D (1832) BT_BTC: btc_thread_handler msg 1 8 0 0x3fcb1298 D (1842) BT_BTC: btc_dm_upstreams_cback ev: 0 D (1842) BT_BTC: Storage load rslt 0 D (1842) BT_BTC: Storage load rslt 1 D (1852) BT_APPL: BTA got event 0x102 D (1852) BT_APPL: bta_dm_sm_execute event:0x2 D (1862) BT_BTC: btc_transfer_context msg 0 2 0 0x3fca17d4 D (1862) BT_BTC: btc_thread_handler msg 0 2 0 0x3fcabe54 D (1872) BT_APPL: BTA got event 0x2000 D (1872) BT_APPL: bta_gatts_enable: num of handle range added=0 D (1882) BT_GATT: gatt_init_srv_chg I (1882) BT_GATT: GATT_Register D (1882) BT_GATT: UUID=[0x0055] I (1892) BT_GATT: allocated gatt_if=3 D (1892) BT_BTC: btc_transfer_context msg 1 2 0 0x3fcafbb0 D (1902) BT_APPL: BTA got event 0x2001 I (1902) BT_GATT: GATT_StartIf gatt_if=3 D (1912) BT_GATT: gatt_find_the_connected_bda start_idx=0 D (1912) BT_BTC: btc_gatts_arg_deep_free Unhandled deep free 0 D (1922) BT_BTC: btc_thread_handler msg 1 2 0 0x3fcaceb4 I (1922) SEC_GATTS_DEMO: ESP_GATTS_REG_EVT D (1932) BT_BTC: btc_transfer_context msg 0 5 10 0x3fcac9c4 D (1932) BT_BTC: btc_transfer_context msg 0 2 3 0x3fcac9c4 D (1942) BT_BTC: btc_thread_handler msg 0 5 10 0x3fcb11f0 D (1952) BT_BTC: btc_gap_ble_call_handler act 10 D (1952) BT_APPL: BTA got event 0x123 D (1952) BT_APPL: bta_dm_sm_execute event:0x23 D (1962) BT_BTM: BTM_BleConfigPrivacy D (1962) BT_BTC: btc_transfer_context msg 1 5 22 0x3fcafa60 D (1972) BT_HCI: HCI Enqueue Comamnd opcode=0x202d D (1972) BT_HCI: Receive packet event_code=0xe D (1982) BT_HCI: btu_hcif_command_complete_evt D (1982) BT_GAP: GAP_BleAttrDBUpdate attr_uuid=0x2aa6 D (1992) BT_GAP: Found attr_uuid=0x2aa6 D (1992) BT_BTC: btc_gap_ble_arg_deep_free D (2002) BT_BTC: Unhandled deep free 10 D (2002) BT_BTC: btc_thread_handler msg 0 2 3 0x3fcabe54 D (2012) BT_APPL: BTA got event 0x2003 D (2012) BT_APPL: create service rcb_idx = 0 I (2012) BT_GATT: GATTS_CreateService D (2022) BT_GATT: gatt_add_pending_new_srv_start D (2022) BT_GATT: enqueue a new pending new srv start D (2032) BT_GATT: Add a new srv chg item D (2032) BT_GATT: allocate_svc_db_buf allocating extra buffer D (2042) BT_GATT: gatts_init_service_db D (2042) BT_GATT: s_hdl = 40 num_handle = 8 D (2052) BT_GATT: add_service_declaration D (2052) BT_GATT: allocate attr 20 bytes D (2062) BT_GATT: =====> handle = [0x0028] uuid16 = [0x2800] perm=0x01 D (2062) BT_APPL: !!!!!!attr_val->attr_len = 4 D (2072) BT_APPL: !!!!!!!attr_val->attr_max_len = 40 D (2072) BT_APPL: BTA got event 0x2006 D (2082) BT_APPL: bta_gatts_find_srvc_cb_by_srvc_id service_id=40 D (2082) BT_APPL: bta_gatts_find_srvc_cb_by_srvc_id found service cb index =0 D (2092) BT_GATT: gatts_add_characteristic perm=0x11 property=0x1a D (2102) BT_GATT: allocate attr 20 bytes D (2102) BT_GATT: =====> handle = [0x0029] uuid16 = [0x2803] perm=0x01 D (2112) BT_GATT: allocate attr 20 bytes D (2112) BT_GATT: =====> handle = [0x002a] uuid16 = [0xff01] perm=0x11 D (2122) BT_GATT: attr_val->attr_len = 4, attr_val->attr_max_len = 40 D (2132) BT_GATT: attribute handle = 2a D (2132) BT_APPL: BTA got event 0x2007 D (2132) BT_APPL: bta_gatts_find_srvc_cb_by_srvc_id service_id=40 D (2142) BT_APPL: bta_gatts_find_srvc_cb_by_srvc_id found service cb index =0 D (2152) BT_GATT: gatts_add_char_descr uuid=0x2902 D (2152) BT_GATT: allocate attr 20 bytes D (2162) BT_GATT: =====> handle = [0x002b] uuid16 = [0x2902] perm=0x11 D (2162) BT_APPL: !!!!!!attr_val->attr_len = 4 D (2172) BT_APPL: !!!!!!!attr_val->attr_max_len = 40 D (2172) BT_APPL: BTA got event 0x2006 D (2182) BT_APPL: bta_gatts_find_srvc_cb_by_srvc_id service_id=40 D (2182) BT_APPL: bta_gatts_find_srvc_cb_by_srvc_id found service cb index =0 D (2192) BT_GATT: gatts_add_characteristic perm=0x11 property=0x2 D (2202) BT_GATT: allocate attr 20 bytes D (2202) BT_GATT: allocate_svc_db_buf allocating extra buffer D (2212) BT_GATT: =====> handle = [0x002c] uuid16 = [0x2803] perm=0x01 D (2212) BT_GATT: allocate attr 20 bytes D (2222) BT_GATT: =====> handle = [0x002d] uuid16 = [0xff02] perm=0x11 D (2222) BT_GATT: attr_val->attr_len = 4, attr_val->attr_max_len = 40 D (2232) BT_GATT: attribute handle = 2d D (2232) BT_APPL: !!!!!!attr_val->attr_len = 4 D (2242) BT_APPL: !!!!!!!attr_val->attr_max_len = 40 D (2242) BT_APPL: BTA got event 0x2006 D (2252) BT_APPL: bta_gatts_find_srvc_cb_by_srvc_id service_id=40 D (2262) BT_APPL: bta_gatts_find_srvc_cb_by_srvc_id found service cb index =0 D (2262) BT_GATT: gatts_add_characteristic perm=0x11 property=0x8 D (2272) BT_GATT: allocate attr 20 bytes D (2272) BT_GATT: =====> handle = [0x002e] uuid16 = [0x2803] perm=0x01 D (2282) BT_GATT: allocate attr 20 bytes D (2282) BT_GATT: =====> handle = [0x002f] uuid16 = [0xff03] perm=0x11 D (2292) BT_GATT: attr_val->attr_len = 4, attr_val->attr_max_len = 40 D (2302) BT_GATT: attribute handle = 2f I (2302) SEC_GATTS_DEMO: The number handle = 8 D (2312) BT_BTC: btc_transfer_context msg 0 2 5 0x3fcac6a4 D (2312) BT_BTC: btc_thread_handler msg 1 5 22 0x3fcb12e8 I (2322) SEC_GATTS_DEMO: ESP_GAP_BLE_SET_LOCAL_PRIVACY_COMPLETE_EVT, tatus = 0 D (2332) BT_BTC: btc_transfer_context msg 0 5 33 0x3fcac9d4 D (2332) BT_BTC: btc_gap_ble_cb_deep_free D (2342) BT_BTC: Unhandled deep free 22 D (2342) BT_BTC: btc_thread_handler msg 0 2 5 0x3fcb11f0 D (2352) BT_APPL: BTA got event 0x2009 D (2352) BT_APPL: bta_gatts_find_srvc_cb_by_srvc_id service_id=40 D (2362) BT_APPL: bta_gatts_find_srvc_cb_by_srvc_id found service cb index =0 I (2362) BT_GATT: GATTS_StartService D (2372) BT_GATT: total buffer in db [2] D (2372) BT_GATT: allocated i_sreg=2 D (2372) BT_GATT: s_hdl=40 e_hdl=47 type=0x2800 svc_inst=0 sdp_hdl=0x0 D (2382) BT_GATT: gatt_sr_is_new_srv_chg: Yes D (2392) BT_GATT: gatt_proc_srv_chg D (2392) BT_GATT: gatt_set_srv_chg D (2392) BT_GATT: gatt_find_the_connected_bda start_idx=0 D (2402) BT_APPL: bta_gatts_start_service service_id= 40 D (2402) BT_BTC: btc_transfer_context msg 1 2 12 0x3fcafbb0 D (2412) BT_BTC: btc_gatts_arg_deep_free Unhandled deep free 5 D (2422) BT_BTC: btc_thread_handler msg 0 5 33 0x3fcace90 D (2422) BT_BTC: btc_gap_ble_call_handler act 33 D (2432) BT_BTC: BTC_GAP_BLE_SET_EXT_ADV_PARAMS I (2432) BT_APPL: BTA_DmBleGapExtAdvSetParams, Set extended ADV parameters. D (2442) BT_APPL: BTA got event 0x14b D (2442) BT_APPL: bta_dm_sm_execute event:0x4b I (2452) BT_APPL: bta_dm_ble_gap_ext_adv_set_params, instance = 0 D (2452) BT_HCI: btsnd_hcic_ble_set_ext_adv_params, adv_handle = 0, properties = 1, interval_min = 32, interval_max = 32, channel_map = 7, own_addr_type = 0, peer_addr_type = 0, adv_filter_policy = 0, adv_tx_power = 127, primary_adv_phy = 1, secondary_adv_max_skip = 0, secondary_adv_phy = 2, adv_sid = 0, scan_req_ntf_enable = 0 D (2492) BT_HCI: HCI Enqueue Comamnd opcode=0x2036 D (2492) BT_HCI: Receive packet event_code=0xe D (2502) BT_HCI: btu_hcif_command_complete_evt D (2502) BT_BTC: btc_transfer_context msg 1 5 34 0x3fcaf9f0 D (2512) BT_HCI: btu_hcif_hdl_command_complete opcode 0x2036 status 0x0 D (2522) BT_BTC: btc_gap_ble_arg_deep_free D (2522) BT_BTC: Unhandled deep free 33 D (2522) BT_BTC: btc_thread_handler msg 1 2 12 0x3fcabe54 D (2532) BT_BTC: btc_thread_handler msg 1 5 34 0x3fcb121c I (2542) SEC_GATTS_DEMO: ESP_GAP_BLE_EXT_ADV_SET_PARAMS_COMPLETE_EVT status 0 D (2542) BT_BTC: btc_transfer_context msg 0 5 34 0x3fcac9d4 D (2552) BT_BTC: btc_gap_ble_cb_deep_free D (2552) BT_BTC: Unhandled deep free 34 D (2562) BT_BTC: btc_thread_handler msg 0 5 34 0x3fcace90 D (2562) BT_BTC: btc_gap_ble_call_handler act 34 D (2572) BT_BTC: BTC_GAP_BLE_CFG_EXT_ADV_DATA_RAW I (2572) BT_APPL: BTA_DmBleGapConfigExtAdvDataRaw, Config extended Adv data. D (2582) BT_APPL: BTA got event 0x14c D (2582) BT_APPL: bta_dm_sm_execute event:0x4c I (2592) BT_APPL: bta_dm_ble_gap_config_ext_adv_data_raw, instance = 0, len = 28 D (2602) BT_HCI: btsnd_hcic_ble_set_ext_adv_data, adv_handle = 0, operation = 3, fragment_prefrence = 0, data_len = 28 D (2612) BT_HCI: HCI Enqueue Comamnd opcode=0x2037 D (2612) BT_HCI: Receive packet event_code=0xe D (2622) BT_HCI: btu_hcif_command_complete_evt D (2622) BT_BTC: btc_transfer_context msg 1 5 35 0x3fcafa10 D (2632) BT_HCI: btu_hcif_hdl_command_complete opcode 0x2037 status 0x0 D (2642) BT_BTC: btc_gap_ble_arg_deep_free D (2642) BT_BTC: btc_thread_handler msg 1 5 35 0x3fcb1284 I (2652) SEC_GATTS_DEMO: ESP_GAP_BLE_EXT_ADV_DATA_SET_COMPLETE_EVT status 0 D (2652) BT_BTC: btc_transfer_context msg 0 5 36 0x3fcac9d4 D (2662) BT_BTC: btc_gap_ble_cb_deep_free D (2662) BT_BTC: Unhandled deep free 35 D (2672) BT_BTC: btc_thread_handler msg 0 5 36 0x3fcace90 D (2672) BT_BTC: btc_gap_ble_call_handler act 36 D (2682) BT_BTC: BTC_GAP_BLE_EXT_ADV_START D (2682) BT_BTC: adv_handle[0] = 0, duration[0] = 0, max_adv_evt[0] = 0 I (2692) BT_APPL: BTA_DmBleGapExtAdvEnable, Start extended ADV D (2702) BT_APPL: BTA got event 0x14d D (2702) BT_APPL: bta_dm_sm_execute event:0x4d I (2702) BT_APPL: bta_dm_ble_gap_start_ext_adv, enable = 1, num = 1 D (2712) BT_HCI: btsnd_hcic_ble_ext_adv_enable, enable = 1, num_of_sets = 1 D (2722) BT_HCI: adv_handle[0] = 0, duration[0] = 0, max_adv_evt[0] = 0 D (2722) BT_HCI: HCI Enqueue Comamnd opcode=0x2039 D (2732) BT_HCI: Receive packet event_code=0xe D (2732) BT_HCI: btu_hcif_command_complete_evt D (2742) BT_BTC: btc_transfer_context msg 1 5 37 0x3fcafa00 D (2742) BT_HCI: btu_hcif_hdl_command_complete opcode 0x2039 status 0x0 D (2752) BT_BTC: btc_gap_ble_arg_deep_free D (2762) BT_BTC: btc_thread_handler msg 1 5 37 0x3fcb1270 I (2762) SEC_GATTS_DEMO: ESP_GAP_BLE_EXT_ADV_START_COMPLETE_EVT, status = 0 D (2772) BT_BTC: btc_gap_ble_cb_deep_free D (2772) BT_BTC: Unhandled deep free 37 D (2782) BT_BTC: btc_transfer_context msg 0 5 20 0x3fca17d4 D (2782) BT_BTC: btc_thread_handler msg 0 5 20 0x3fcace90 D (2792) BT_BTC: btc_gap_ble_call_handler act 20 D (2792) BT_APPL: BTA got event 0x115 D (2802) BT_APPL: bta_dm_sm_execute event:0x15 D (2802) BT_SMP: static passkey 123456 D (2812) BT_BTC: btc_gap_ble_arg_deep_free D (2812) BT_BTC: btc_transfer_context msg 0 5 20 0x3fca17d4 D (2822) BT_BTC: btc_thread_handler msg 0 5 20 0x3fcace90 D (2822) BT_BTC: btc_gap_ble_call_handler act 20 D (2832) BT_BTC: btc_gap_ble_arg_deep_free D (2832) BT_BTC: btc_transfer_context msg 0 5 20 0x3fca17d4 D (2842) BT_BTC: btc_thread_handler msg 0 5 20 0x3fcace90 D (2842) BT_BTC: btc_gap_ble_call_handler act 20 D (2852) BT_BTC: btc_gap_ble_arg_deep_free D (2852) BT_BTC: btc_transfer_context msg 0 5 20 0x3fca17d4 D (2862) BT_BTC: btc_thread_handler msg 0 5 20 0x3fcace90 D (2862) BT_BTC: btc_gap_ble_call_handler act 20 D (2872) BT_BTC: btc_gap_ble_arg_deep_free D (2872) BT_BTC: btc_transfer_context msg 0 5 20 0x3fca17d4 D (2882) BT_BTC: btc_thread_handler msg 0 5 20 0x3fcace90 D (2882) BT_BTC: btc_gap_ble_call_handler act 20 D (2892) BT_BTC: btc_gap_ble_arg_deep_free D (2892) BT_BTC: btc_transfer_context msg 0 5 20 0x3fca17d4 D (2902) BT_BTC: btc_thread_handler msg 0 5 20 0x3fcace90 D (2902) BT_BTC: btc_gap_ble_call_handler act 20 D (2912) BT_BTC: btc_gap_ble_arg_deep_free D (2912) BT_BTC: btc_transfer_context msg 0 5 20 0x3fca17d4 D (2922) BT_BTC: btc_thread_handler msg 0 5 20 0x3fcace90 D (2922) BT_BTC: btc_gap_ble_call_handler act 20 D (2932) BT_BTC: btc_gap_ble_arg_deep_free D (2932) BT_BTC: btc_transfer_context msg 0 5 20 0x3fca17d4 D (2942) BT_BTC: btc_thread_handler msg 0 5 20 0x3fcace90 D (2952) BT_BTC: btc_gap_ble_call_handler act 20 D (2952) BT_BTC: btc_gap_ble_arg_deep_free ```

Debug Log (after trying to connect)

``` D (45252) BT_HCI: Receive packet event_code=0x3e D (45252) BT_HCI: Receive packet event_code=0x3e D (45252) BT_HCI: Receive packet event_code=0x3e D (45262) BT_HCI: BLE HCI(id=62) event = 0x0a) D (45262) BT_BTM: status = 0, handle = 1, role = 1, bda_type = 1 D (45272) BT_BTM: btm_identity_addr_to_random_pseudo D (45272) BT_BTM: btm_ble_resolve_random_addr D (45282) BT_BTM: btm_ble_resolve_address_cmpl p_mgnt_cb->p_dev_rec = 0x00000000 D (45282) BT_BTM: btm_ble_resolve_random_addr_on_conn_cmpl D (45292) BT_BTM: btm_ble_resolve_random_addr_on_conn_cmpl unable to match and resolve random address D (45292) BT_HCI: Receive packet event_code=0x3e D (45302) BT_BTM: btm_ble_connected D (45312) BT_BTM: btm_sec_alloc_dev I (45312) BT_BTM: BTM_InqDbRead: bd addr [78a6af47e410] D (45322) BT_BTM: BTM_GetHCIConnHandle D (45322) BT_BTM: BTM_GetHCIConnHandle D (45322) BT_HCI: btu_free_timer Unable to find expected alarm in hashmap D (45332) BT_HCI: btu_free_timer Unable to find expected alarm in hashmap D (45342) BT_HCI: btu_free_timer Unable to find expected alarm in hashmap D (45352) BT_L2CAP: l2c_ble_link_adjust_allocation num_hipri: 0 num_lowpri: 1 low_quota: 12 round_robin_quota: 0 qq: 12 D (45362) BT_L2CAP: l2c_ble_link_adjust_allocation Priority: 0 XmitQuota: 12 D (45362) BT_L2CAP: SentNotAcked: 0 RRUnacked: 0 D (45372) BT_L2CAP: l2cu_allocate_ccb: cid 0x0000 D (45372) BT_HCI: btu_free_quick_timer Unable to find expected alarm in hashmap D (45382) BT_HCI: btu_free_quick_timer Unable to find expected alarm in hashmap D (45392) BT_HCI: btu_free_timer Unable to find expected alarm in hashmap D (45402) BT_L2CAP: l2c_link_adjust_chnl_allocation D (45402) BT_L2CAP: CID:0x0040 FCR Mode:0 Priority:2 TxDataRate:1 RxDataRate:1 Quota:20 D (45412) BT_BTM: btm_find_or_alloc_dev D (45412) BT_BTM: btm_acl_created hci_handle=1 link_role=1 transport=2 D (45422) BT_BTM: device_type=0x2 D (45422) BT_HCI: HCI Enqueue Comamnd opcode=0x41d D (45432) BT_HCI: Receive packet event_code=0xf D (45432) BT_HCI: Receive packet event_code=0xc D (45442) BT_HCI: BLE HCI(id=62) event = 0x14) D (45442) BT_HCI: BLE HCI(id=62) event = 0x12) D (45452) BT_BTC: btc_transfer_context msg 1 5 58 0x3fcafa10 D (45452) BT_HCI: BLE HCI(id=62) event = 0x05) D (45462) BT_BTM: btm_ble_ltk_request D (45462) BT_SMP: smp_proc_ltk_request state = 0 D (45472) BT_BTM: btm_ble_ltk_request_reply D (45472) BT_BTM: key size = 0 D (45472) BT_HCI: HCI Enqueue Comamnd opcode=0x201b D (45482) BT_HCI: Receive packet event_code=0xe D (45482) BT_HCI: btu_hcif_command_complete_evt D (45492) BT_BTM: btm_read_remote_version_complete D (45492) BT_BTM: btm_handle_to_acl_index: 1 D (45492) BT_HCI: Receive packet event_code=0x5 D (45502) BT_HCI: HCI Enqueue Comamnd opcode=0x2016 D (45512) BT_HCI: Receive packet event_code=0xf D (45512) BT_HCI: btu_free_timer Unable to find expected alarm in hashmap D (45522) BT_HCI: btu_free_timer Unable to find expected alarm in hashmap D (45532) BT_HCI: btu_free_timer Unable to find expected alarm in hashmap D (45532) BT_L2CAP: l2cu_release_ccb: cid 0x0004 in_use: 1 D (45542) BT_HCI: btu_free_timer Unable to find expected alarm in hashmap D (45552) BT_GATT: GATT ATT protocol channel with BDA: 78a6af47e410 is disconnected D (45552) BT_GATT: gatt_is_bda_in_the_srv_chg_clt_list :78-a6-af-47-e4-10 D (45562) BT_BTM: btm_sec_is_a_bonded_dev() is_bonded=0 D (45572) BT_GATT: gatt_cleanup_upon_disc D (45572) BT_GATT: exit gatt_cleanup_upon_disc D (45572) BT_GATT: gatt_delete_dev_from_srv_chg_clt_list D (45582) BT_GATT: gatt_is_bda_in_the_srv_chg_clt_list :78-a6-af-47-e4-10 D (45592) BT_GATT: ATT disconnected D (45592) BT_SMP: SMDBG l2c smp_connect_callback D (45592) BT_HCI: btu_free_timer Unable to find expected alarm in hashmap D (45602) BT_BTM: btm_acl_removed D (45602) BT_BTM: btm_acl_report_role_change D (45612) BT_BTM: acl hci_handle=1 transport=2 connectable_mode=0x0 link_role=1 D (45622) BT_BTM: before update p_dev_rec->sec_flags=0x80 D (45622) BT_BTM: LE link down D (45632) BT_BTM: Not Bonded D (45632) BT_BTM: after update p_dev_rec->sec_flags=0x80 D (45632) BT_BTM: btm_handle_to_acl_index: 1 D (45642) BT_BTM: btm_sec_disconnected before update sec_flags=0x80 D (45652) BT_BTM: btm_sec_disconnected after update sec_flags=0x80 W (45652) BT_HCI: hcif disc complete: hdl 0x1, rsn 0x13 D (45662) BT_BTC: btc_thread_handler msg 1 5 58 0x3fca0dfc I (45662) SEC_GATTS_DEMO: ESP_GAP_BLE_ADV_TERMINATED_EVT, status = 0 I (45672) SEC_GATTS_DEMO: ADV successfully ended with a connection being created D (45682) BT_BTC: btc_gap_ble_cb_deep_free D (45682) BT_BTC: Unhandled deep free 58 ```

vabatta commented 1 year ago

I resolved the issue. The problem was that on my two clients (phone, laptop) a paired device appeared in Bluetooth devices, rejecting all connection when running a different program (the two examples). This device only appeared in the list after I did a reboot on MacOS, it was present on iPhone right away.

@SumeetSingh19 Increasing the stack size of NimBLE Host task stack size, I was able to successfully run the example with encryption.

Thanks!

espressif / esp-idf