esp-idf: Task watchdog got triggered in BLE functions (IDFGH-2271)

Recently I have started experimenting with NimBLE and in after some time I started to get these errors:

E (233591) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
E (233591) task_wdt:  - IDLE0 (CPU 0)
E (233591) task_wdt: Tasks currently running:
E (233591) task_wdt: CPU 0: ble
E (233591) task_wdt: CPU 1: IDLE1

I made some research and found out that this error potentionally could be fixed by putting vTaskDelay in these functions:

  • nimble_port_run
  • ble_ll_task

I’m not sure that’s the right way to fix the problem so please let me know if there is more information needed. The problem occures on master branch, and I have not checked older branches.

E (31838) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
E (31838) task_wdt:  - IDLE0 (CPU 0)
E (31838) task_wdt: Tasks currently running:
E (31838) task_wdt: CPU 0: ble
E (31838) task_wdt: CPU 1: IDLE1
E (31838) task_wdt: Aborting.
abort() was called at PC 0x400d2a4f on core 0
0x400d2a4f: task_wdt_isr at /home/ildus/dev/esp-idf/components/esp32/task_wdt.c:174 (discriminator 1)


ELF file SHA256: f44515713f51fd804b7e83af6ede154af92a1a878348499d29c57e90fad272ce

Backtrace: 0x4008e7ad:0x3ffbe360 0x4008eb35:0x3ffbe380 0x400d2a4f:0x3ffbe3a0 0x40082aad:0x3ffbe3c0 0x4000bfed:0x3ffc7730 |<-CORRUPTED
0x4008e7ad: invoke_abort at /home/ildus/dev/esp-idf/components/esp32/panic.c:157

0x4008eb35: abort at /home/ildus/dev/esp-idf/components/esp32/panic.c:174

0x400d2a4f: task_wdt_isr at /home/ildus/dev/esp-idf/components/esp32/task_wdt.c:174 (discriminator 1)

0x40082aad: _xt_lowint1 at /home/ildus/dev/esp-idf/components/freertos/xtensa_vectors.S:1153

This happens on ESP-WROOM-32 on bleprph example.

About this issue

  • Original URL
  • State: closed
  • Created 5 years ago
  • Comments: 27 (10 by maintainers)

Commits related to this issue

Most upvoted comments

Thanks @prasad-alatkar. Sadly I was unable to reproduce the issue before and after the patch. I updated the ESP-IDF to v:latest, no issue there. @albertmbt, do you have time to look into this?

I keep trying and get back to this when I know more.

Hi @Unsigus Thank you for reporting this issue, I am attaching a temporary patch here to be applied at $IDF_PATH/components/bt/host/nimble/nimble. Could you please test and let me know if it resolves your issue ? patch: NimBLE_CCCD_overflow_loop_fix.zip

Here you go

I (29) boot: ESP-IDF v4.2-dev-701-g0ae960f2f-dirty 2nd stage bootloader
I (29) boot: compile time 14:03:03
I (30) boot: chip revision: 1
I (34) boot_comm: chip revision: 1, min. bootloader chip revision: 0
I (41) boot.esp32: SPI Speed      : 40MHz
I (46) boot.esp32: SPI Mode       : DIO
I (50) boot.esp32: SPI Flash Size : 2MB
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 (78) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (86) boot:  2 factory          factory app      00 00 00010000 00100000
I (93) boot: End of partition table
I (98) boot_comm: chip revision: 1, min. application chip revision: 0
I (105) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x0e898 ( 59544) map
I (136) esp_image: segment 1: paddr=0x0001e8c0 vaddr=0x3ffbdb60 size=0x01758 (  5976) load
I (139) esp_image: segment 2: paddr=0x00020020 vaddr=0x400d0020 size=0x55820 (350240) map
0x400d0020: _stext at ??:?

I (276) esp_image: segment 3: paddr=0x00075848 vaddr=0x3ffbf2b8 size=0x01d24 (  7460) load
I (280) esp_image: segment 4: paddr=0x00077574 vaddr=0x40080000 size=0x00404 (  1028) load
0x40080000: _WindowOverflow4 at ~/esp/esp-idf/components/freertos/xtensa/xtensa_vectors.S:1817

I (284) esp_image: segment 5: paddr=0x00077980 vaddr=0x40080404 size=0x137e4 ( 79844) load
I (337) boot: Loaded app from partition at offset 0x10000
I (337) boot: Disabling RNG early entropy source...
I (338) cpu_start: Pro cpu up.
I (341) cpu_start: Application information:
I (346) cpu_start: Project name:     bleprph
I (351) cpu_start: App version:      v4.2-dev-701-g0ae960f2f-dirty
I (358) cpu_start: Compile time:     Mar 20 2020 14:02:56
I (364) cpu_start: ELF file SHA256:  807a1f7926ac86cb...
I (370) cpu_start: ESP-IDF:          v4.2-dev-701-g0ae960f2f-dirty
I (377) cpu_start: Starting app cpu, entry point is 0x400812fc
0x400812fc: call_start_cpu1 at ~/esp/esp-idf/components/esp32/cpu_start.c:273

I (0) cpu_start: App cpu up.
D (387) memory_layout: Checking 11 reserved memory ranges:
D (393) memory_layout: Reserved memory range 0x3ffae000 - 0x3ffae6e0
D (399) memory_layout: Reserved memory range 0x3ffae6e0 - 0x3ffaff10
D (405) memory_layout: Reserved memory range 0x3ffb0000 - 0x3ffb6388
D (412) memory_layout: Reserved memory range 0x3ffb8000 - 0x3ffb9a20
D (418) memory_layout: Reserved memory range 0x3ffbdb28 - 0x3ffbdb5c
D (425) memory_layout: Reserved memory range 0x3ffbdb60 - 0x3ffc3bd0
D (431) memory_layout: Reserved memory range 0x3ffe0000 - 0x3ffe0440
D (438) memory_layout: Reserved memory range 0x3ffe3f20 - 0x3ffe4350
D (444) memory_layout: Reserved memory range 0x40070000 - 0x40078000
D (450) memory_layout: Reserved memory range 0x40078000 - 0x40080000
0x40080000: _WindowOverflow4 at ~esp/esp-idf/components/freertos/xtensa/xtensa_vectors.S:1817

D (457) memory_layout: Reserved memory range 0x40080000 - 0x40093be8
0x40080000: _WindowOverflow4 at ~/esp/esp-idf/components/freertos/xtensa/xtensa_vectors.S:1817

D (463) memory_layout: Building list of available memory regions:
D (469) memory_layout: Available memory region 0x3ffaff10 - 0x3ffb0000
D (476) memory_layout: Available memory region 0x3ffb6388 - 0x3ffb8000
D (483) memory_layout: Available memory region 0x3ffb9a20 - 0x3ffbdb28
D (489) memory_layout: Available memory region 0x3ffbdb5c - 0x3ffbdb60
D (496) memory_layout: Available memory region 0x3ffc3bd0 - 0x3ffc4000
D (502) memory_layout: Available memory region 0x3ffc4000 - 0x3ffc6000
D (509) memory_layout: Available memory region 0x3ffc6000 - 0x3ffc8000
D (516) memory_layout: Available memory region 0x3ffc8000 - 0x3ffca000
D (522) memory_layout: Available memory region 0x3ffca000 - 0x3ffcc000
D (529) memory_layout: Available memory region 0x3ffcc000 - 0x3ffce000
D (535) memory_layout: Available memory region 0x3ffce000 - 0x3ffd0000
D (542) memory_layout: Available memory region 0x3ffd0000 - 0x3ffd2000
D (549) memory_layout: Available memory region 0x3ffd2000 - 0x3ffd4000
D (555) memory_layout: Available memory region 0x3ffd4000 - 0x3ffd6000
D (562) memory_layout: Available memory region 0x3ffd6000 - 0x3ffd8000
D (568) memory_layout: Available memory region 0x3ffd8000 - 0x3ffda000
D (575) memory_layout: Available memory region 0x3ffda000 - 0x3ffdc000
D (582) memory_layout: Available memory region 0x3ffdc000 - 0x3ffde000
D (588) memory_layout: Available memory region 0x3ffde000 - 0x3ffe0000
D (595) memory_layout: Available memory region 0x3ffe0440 - 0x3ffe3f20
D (601) memory_layout: Available memory region 0x3ffe4350 - 0x3ffe8000
D (608) memory_layout: Available memory region 0x3ffe8000 - 0x3fff0000
D (615) memory_layout: Available memory region 0x3fff0000 - 0x3fff8000
D (621) memory_layout: Available memory region 0x3fff8000 - 0x3fffc000
D (628) memory_layout: Available memory region 0x3fffc000 - 0x40000000
D (634) memory_layout: Available memory region 0x40093be8 - 0x40094000
D (641) memory_layout: Available memory region 0x40094000 - 0x40096000
D (648) memory_layout: Available memory region 0x40096000 - 0x40098000
D (654) memory_layout: Available memory region 0x40098000 - 0x4009a000
D (661) memory_layout: Available memory region 0x4009a000 - 0x4009c000
D (667) memory_layout: Available memory region 0x4009c000 - 0x4009e000
D (674) memory_layout: Available memory region 0x4009e000 - 0x400a0000
I (681) heap_init: Initializing. RAM available for dynamic allocation:
D (688) heap_init: New heap initialised at 0x3ffaff10
I (693) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
D (699) heap_init: New heap initialised at 0x3ffb6388
I (704) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
D (710) heap_init: New heap initialised at 0x3ffb9a20
I (715) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (721) heap_init: At 3FFBDB5C len 00000004 (0 KiB): DRAM
D (728) heap_init: New heap initialised at 0x3ffc3bd0
I (733) heap_init: At 3FFC3BD0 len 0001C430 (113 KiB): DRAM
I (739) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (745) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
D (752) heap_init: New heap initialised at 0x40093be8
I (757) heap_init: At 40093BE8 len 0000C418 (49 KiB): IRAM
I (763) cpu_start: Pro cpu start user code
D (775) clk: RTC_SLOW_CLK calibration value: 3752806
D (785) intr_alloc: Connected src 46 to int 2 (cpu 0)
D (785) intr_alloc: Connected src 17 to int 3 (cpu 0)
D (786) intr_alloc: Connected src 24 to int 9 (cpu 0)
D (791) FLASH_HAL: extra_dummy: 1
D (794) spi_flash: trying chip: issi
D (797) spi_flash: trying chip: gd
I (801) spi_flash: detected chip: gd
I (805) spi_flash: flash io: dio
D (809) chip_generic: set_io_mode: status before 0x0
W (814) spi_flash: Detected size(16384k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (827) cpu_start: Starting scheduler on PRO CPU.
D (0) intr_alloc: Connected src 25 to int 2 (cpu 1)
I (0) cpu_start: Starting scheduler on APP CPU.
D (843) heap_init: New heap initialised at 0x3ffe0440
D (853) heap_init: New heap initialised at 0x3ffe4350
D (863) intr_alloc: Connected src 16 to int 12 (cpu 0)
D (863) partition: Loading the partition table
D (913) BTDM_INIT: Release DRAM [0x3ffb2730] - [0x3ffb6388]
I (913) BTDM_INIT: BT controller compile version [ab2cbc7]
D (913) BTDM_INIT: .data initialise [0x3ffae6e0] <== [0x4000d890]
D (913) BTDM_INIT: .bss initialise [0x3ffb0000] - [0x3ffb09a8]
D (923) BTDM_INIT: .bss initialise [0x3ffb09a8] - [0x3ffb1ddc]
D (923) BTDM_INIT: .bss initialise [0x3ffb1ddc] - [0x3ffb2730]
D (933) BTDM_INIT: .bss initialise [0x3ffb8000] - [0x3ffb9a20]
D (943) BTDM_INIT: .bss initialise [0x3ffbdb28] - [0x3ffbdb5c]
I (943) system_api: Base MAC address is not set
I (953) system_api: read default base MAC address from EFUSE
D (953) efuse: coding scheme 0
D (963) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 8 bit
D (963) efuse: coding scheme 0
D (973) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 0 bit
D (973) efuse: coding scheme 0
D (983) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 24 bit
D (983) efuse: coding scheme 0
D (993) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 16 bit
D (993) efuse: coding scheme 0
D (1003) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 8 bit
D (1003) efuse: coding scheme 0
D (1013) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 0 bit
D (1013) efuse: coding scheme 0
D (1023) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 16 bit
D (1033) phy_init: loading PHY init data from application binary
D (1033) nvs: nvs_open_from_partition phy 0
D (1043) nvs: nvs_get cal_version 4
D (1043) nvs: nvs_get_str_or_blob cal_mac
D (1043) efuse: coding scheme 0
D (1053) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 8 bit
D (1053) efuse: coding scheme 0
D (1063) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 0 bit
D (1063) efuse: coding scheme 0
D (1073) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 24 bit
D (1073) efuse: coding scheme 0
D (1083) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 16 bit
D (1083) efuse: coding scheme 0
D (1093) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 8 bit
D (1093) efuse: coding scheme 0
D (1103) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 0 bit
D (1103) efuse: coding scheme 0
D (1113) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 16 bit
D (1123) nvs: nvs_get_str_or_blob cal_data
D (1133) nvs: nvs_close 1
D (1133) efuse: coding scheme 0
D (1133) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 8 bit
D (1133) efuse: coding scheme 0
D (1143) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 0 bit
D (1143) efuse: coding scheme 0
D (1153) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 24 bit
D (1153) efuse: coding scheme 0
D (1163) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 16 bit
D (1163) efuse: coding scheme 0
D (1173) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 8 bit
D (1173) efuse: coding scheme 0
D (1183) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 0 bit
D (1183) efuse: coding scheme 0
D (1193) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 16 bit
I (1283) phy: phy_version: 4180, cb3948e, Sep 12 2019, 16:39:13, 0, 0
D (1513) nvs: nvs_open_from_partition nimble_bond 1
D (1523) nvs: nvs_get_str_or_blob our_sec_1
D (1523) nvs: nvs_close 2
D (1523) nvs: nvs_open_from_partition nimble_bond 1
D (1523) nvs: nvs_get_str_or_blob our_sec_2
D (1533) nvs: nvs_close 3
D (1533) nvs: nvs_open_from_partition nimble_bond 1
D (1533) nvs: nvs_get_str_or_blob our_sec_3
D (1543) nvs: nvs_close 4
D (1543) NIMBLE_NVS: ble_store_config_our_secs restored 0 bonds
D (1553) nvs: nvs_open_from_partition nimble_bond 1
D (1553) nvs: nvs_get_str_or_blob peer_sec_1
D (1563) nvs: nvs_close 5
D (1563) nvs: nvs_open_from_partition nimble_bond 1
D (1563) nvs: nvs_get_str_or_blob peer_sec_2
D (1573) nvs: nvs_close 6
D (1573) nvs: nvs_open_from_partition nimble_bond 1
D (1573) nvs: nvs_get_str_or_blob peer_sec_3
D (1583) nvs: nvs_close 7
D (1583) NIMBLE_NVS: ble_store_config_peer_secs restored 0 bonds
D (1593) nvs: nvs_open_from_partition nimble_bond 1
D (1593) nvs: nvs_get_str_or_blob cccd_sec_1
D (1603) nvs: nvs_get_str_or_blob cccd_sec_1
D (1603) nvs: nvs_close 8
D (1603) NIMBLE_NVS: CCCD in RAM is filled up from NVS index = 1
D (1613) nvs: nvs_open_from_partition nimble_bond 1
D (1623) nvs: nvs_get_str_or_blob cccd_sec_2
D (1623) nvs: nvs_get_str_or_blob cccd_sec_2
D (1623) nvs: nvs_close 9
D (1633) NIMBLE_NVS: CCCD in RAM is filled up from NVS index = 2
D (1633) nvs: nvs_open_from_partition nimble_bond 1
D (1643) nvs: nvs_get_str_or_blob cccd_sec_3
D (1643) nvs: nvs_get_str_or_blob cccd_sec_3
D (1653) nvs: nvs_close 10
D (1653) NIMBLE_NVS: CCCD in RAM is filled up from NVS index = 3
D (1663) nvs: nvs_open_from_partition nimble_bond 1
D (1663) nvs: nvs_get_str_or_blob cccd_sec_4
D (1663) nvs: nvs_get_str_or_blob cccd_sec_4
D (1673) nvs: nvs_close 11
D (1673) NIMBLE_NVS: CCCD in RAM is filled up from NVS index = 4
D (1683) nvs: nvs_open_from_partition nimble_bond 1
D (1683) nvs: nvs_get_str_or_blob cccd_sec_5
D (1693) nvs: nvs_close 12
D (1693) nvs: nvs_open_from_partition nimble_bond 1
D (1693) nvs: nvs_get_str_or_blob cccd_sec_6
D (1703) nvs: nvs_close 13
D (1703) nvs: nvs_open_from_partition nimble_bond 1
D (1713) nvs: nvs_get_str_or_blob cccd_sec_7
D (1713) nvs: nvs_close 14
D (1713) nvs: nvs_open_from_partition nimble_bond 1
D (1723) nvs: nvs_get_str_or_blob cccd_sec_8
D (1723) nvs: nvs_close 15
D (1733) NIMBLE_NVS: ble_store_config_cccds restored 4 bonds
D (1733) nvs: nvs_open_from_partition nimble_bond 1
D (1743) nvs: nvs_get_str_or_blob p_dev_rec_1
D (1743) nvs: nvs_close 16
D (1743) nvs: nvs_open_from_partition nimble_bond 1
D (1753) nvs: nvs_get_str_or_blob p_dev_rec_2
D (1753) nvs: nvs_close 17
D (1763) nvs: nvs_open_from_partition nimble_bond 1
D (1763) nvs: nvs_get_str_or_blob p_dev_rec_3
D (1773) nvs: nvs_close 18
D (1773) nvs: nvs_open_from_partition nimble_bond 1
D (1773) nvs: nvs_get_str_or_blob p_dev_rec_4
D (1783) nvs: nvs_close 19
D (1783) NIMBLE_NVS: peer_dev_rec restored 0 records
I (1793) NimBLE_BLE_PRPH: BLE Host Task Started
registered service 0x1800 with handle=1
registering characteristic 0x2a00 with def_handle=2 val_handle=3
registering characteristic 0x2a01 with def_handle=4 val_handle=5
registered service 0x1801 with handle=6
registering characteristic 0x2a05 with def_handle=7 val_handle=8
registered service 59462f12-9543-9999-12c8-58b459a2712d with handle=10
registering characteristic 5c3a659e-897e-45e1-b016-007107c96df6 with def_handle=11 val_handle=12
registering characteristic 5c3a659e-897e-45e1-b016-007107c96df7 with def_handle=13 val_handle=14
ble_hs_hci_cmd_send: ogf=0x03 ocf=0x0003 len=0
0x03 0x0c 0x00
I (1843) uart: queue free spaces: 8
D (1853) intr_alloc: Connected src 34 to int 3 (cpu 1)
Command complete: cmd_pkts=5 ogf=0x3 ocf=0x3 status=0
ble_hs_hci_cmd_send: ogf=0x04 ocf=0x0001 len=0
0x01 0x10 0x00
Command complete: cmd_pkts=5 ogf=0x4 ocf=0x1 status=0 hci_ver=8 hci_rev=782 lmp_ver=8 mfrg=96 lmp_subver=782
ble_hs_hci_cmd_send: ogf=0x04 ocf=0x0003 len=0
0x03 0x10 0x00
Command complete: cmd_pkts=5 ogf=0x4 ocf=0x3 status=0 supp_feat=0x877bffdbfecdeebf
ble_hs_hci_cmd_send: ogf=0x03 ocf=0x0001 len=8
0x01 0x0c 0x08 0x90 0x80 0x00 0x02 0x00 0x80 0x00 0x20
Command complete: cmd_pkts=5 ogf=0x3 ocf=0x1 status=0
ble_hs_hci_cmd_send: ogf=0x03 ocf=0x0063 len=8
0x63 0x0c 0x08 0x00 0x00 0x80 0x00 0x00 0x00 0x00 0x00
Command complete: cmd_pkts=5 ogf=0x3 ocf=0x63 status=0
ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0001 len=8
0x01 0x20 0x08 0x7f 0x06 0x00 0x00 0x00 0x00 0x00 0x00
Command complete: cmd_pkts=5 ogf=0x8 ocf=0x1 status=0
ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0002 len=0
0x02 0x20 0x00
Command complete: cmd_pkts=5 ogf=0x8 ocf=0x2 status=0
ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0003 len=0
0x03 0x20 0x00
Command complete: cmd_pkts=5 ogf=0x8 ocf=0x3 status=0
ble_hs_hci_cmd_send: ogf=0x04 ocf=0x0009 len=0
0x09 0x10 0x00
Command complete: cmd_pkts=5 ogf=0x4 ocf=0x9 status=0 bd_addr=bc:dd:c2:d4:fc:22
ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0018 len=0
0x18 0x20 0x00
Command complete: cmd_pkts=5 ogf=0x8 ocf=0x18 status=0 rand=0x8314953b378ae30c
ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0018 len=0
0x18 0x20 0x00
Command complete: cmd_pkts=5 ogf=0x8 ocf=0x18 status=0 rand=0xf96ab7628045758b
Device added to RL, Resolving list count = 1
ble_hs_hci_cmd_send: ogf=0x03 ocf=0x0031 len=1
0x31 0x0c 0x01 0x01
Command complete: cmd_pkts=5 ogf=0x3 ocf=0x31 status=0
ble_hs_hci_cmd_send: ogf=0x03 ocf=0x0033 len=7
0x33 0x0c 0x07 0xff 0x00 0x00 0x0c 0x00 0x00 0x00
Command complete: cmd_pkts=5 ogf=0x3 ocf=0x33 status=17
ble_hs_hci_cmd_send: ogf=0x03 ocf=0x0031 len=1
0x31 0x0c 0x01 0x00
Command complete: cmd_pkts=5 ogf=0x3 ocf=0x31 status=0
looking up peer sec;
Device Address: bc:dd:c2:d4:fc:22
ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0007 len=0
0x07 0x20 0x00
Command complete: cmd_pkts=5 ogf=0x8 ocf=0x7 status=0
ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0008 len=32
0x08 0x20 0x20 0x1a 0x02 0x01 0x06 0x03 0x03 0x11 0x18 0x0f 0x09 0x6e 0x69 0x6d 0x62 0x6c 0x65 0x2d 0x62 0x6c 0x65 0x70 0x72 0x70 0x68 0x02 0x0a 0x03 0x00 0x00 0x00 0x00 0x00
Command complete: cmd_pkts=5 ogf=0x8 ocf=0x8 status=0
GAP procedure initiated: advertise; disc_mode=2 adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0
ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0006 len=15
0x06 0x20 0x0f 0x30 0x00 0x60 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x07 0x00
Command complete: cmd_pkts=5 ogf=0x8 ocf=0x6 status=0
ble_hs_hci_cmd_send: ogf=0x08 ocf=0x000a len=1
0x0a 0x20 0x01 0x01
Command complete: cmd_pkts=5 ogf=0x8 ocf=0xa status=0
LE connection complete. handle=0 role=1 paddrtype=1 addr=fa.c.85.5c.f9.e8 local_rpa=0.0.0.0.0.0 peer_rpa=0.0.0.0.0.0 itvl=6 latency=0 spvn_tmo=400 mca=7
connection established; status=0 handle=0 our_ota_addr_type=0 our_ota_addr=bc:dd:c2:d4:fc:22 our_id_addr_type=0 our_id_addr=bc:dd:c2:d4:fc:22 peer_ota_addr_type=1 peer_ota_addr=fa:0c:85:5c:f9:e8 peer_id_addr_type=1 peer_id_addr=fa:0c:85:5c:f9:e8 conn_itvl=6 conn_latency=0 supervision_timeout=400 encrypted=0 authenticated=0 bonded=0

ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0016 len=2
0x16 0x20 0x02 0x00 0x00
Command Status: status=0 cmd_pkts=5 ocf=0x16 ogf=0x8
ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=11 data=0x07 0x00 0x04 0x00 0x10 0x01 0x00 0xff 0xff 0x00 0x28
rxed att command: read group type req; conn=0 start_handle=0x0001 end_handle=0xffff
txed att command: read group type rsp; conn=0 length=6
host tx hci data; handle=0 length=18
ble_hs_hci_acl_tx(): 0x00 0x00 0x12 0x00 0x0e 0x00 0x04 0x00 0x11 0x06 0x01 0x00 0x05 0x00 0x00 0x18 0x06 0x00 0x09 0x00 0x01 0x18
LE Remote Used Features. FAIL (status=26)
Number of Completed Packets: num_handles=1
handle:0 pkts:1
ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=11 data=0x07 0x00 0x04 0x00 0x10 0x0a 0x00 0xff 0xff 0x00 0x28
rxed att command: read group type req; conn=0 start_handle=0x000a end_handle=0xffff
txed att command: read group type rsp; conn=0 length=20
host tx hci data; handle=0 length=26
ble_hs_hci_acl_tx(): 0x00 0x00 0x1a 0x00 0x16 0x00 0x04 0x00 0x11 0x14 0x0a 0x00 0xff 0xff 0x2d 0x71 0xa2 0x59 0xb4 0x58 0xc8 0x12 0x99 0x99 0x43 0x95 0x12 0x2f 0x46 0x59
Number of Completed Packets: num_handles=1
handle:0 pkts:1
ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=7 data=0x03 0x00 0x04 0x00 0x0a 0x0a 0x00
rxed att command: read req; conn=0 handle=0x000a
host tx hci data; handle=0 length=21
ble_hs_hci_acl_tx(): 0x00 0x00 0x15 0x00 0x11 0x00 0x04 0x00 0x0b 0x2d 0x71 0xa2 0x59 0xb4 0x58 0xc8 0x12 0x99 0x99 0x43 0x95 0x12 0x2f 0x46 0x59
Number of Completed Packets: num_handles=1
handle:0 pkts:1
ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=11 data=0x07 0x00 0x04 0x00 0x08 0x01 0x00 0x05 0x00 0x03 0x28
rxed att command: read type req; conn=0 start_handle=0x0001 end_handle=0x0005
txed att command: read type rsp; conn=0 length=7
host tx hci data; handle=0 length=20
ble_hs_hci_acl_tx(): 0x00 0x00 0x14 0x00 0x10 0x00 0x04 0x00 0x09 0x07 0x02 0x00 0x02 0x03 0x00 0x00 0x2a 0x04 0x00 0x02 0x05 0x00 0x01 0x2a
Number of Completed Packets: num_handles=1
handle:0 pkts:1
ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=7 data=0x03 0x00 0x04 0x00 0x0a 0x03 0x00
rxed att command: read req; conn=0 handle=0x0003
host tx hci data; handle=0 length=19
ble_hs_hci_acl_tx(): 0x00 0x00 0x13 0x00 0x0f 0x00 0x04 0x00 0x0b 0x6e 0x69 0x6d 0x62 0x6c 0x65 0x2d 0x62 0x6c 0x65 0x70 0x72 0x70 0x68
Number of Completed Packets: num_handles=1
handle:0 pkts:1
ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=7 data=0x03 0x00 0x04 0x00 0x0a 0x05 0x00
rxed att command: read req; conn=0 handle=0x0005
host tx hci data; handle=0 length=7
ble_hs_hci_acl_tx(): 0x00 0x00 0x07 0x00 0x03 0x00 0x04 0x00 0x0b 0x00 0x00
Number of Completed Packets: num_handles=1
handle:0 pkts:1
ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=9 data=0x05 0x00 0x04 0x00 0x04 0x04 0x00 0x05 0x00
rxed att command: find info req; conn=0 start_handle=0x0004 end_handle=0x0005
txed att command: find info rsp; conn=0 format=1
host tx hci data; handle=0 length=14
ble_hs_hci_acl_tx(): 0x00 0x00 0x0e 0x00 0x0a 0x00 0x04 0x00 0x05 0x01 0x04 0x00 0x03 0x28 0x05 0x00 0x01 0x2a
Number of Completed Packets: num_handles=1
handle:0 pkts:1
ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=9 data=0x05 0x00 0x04 0x00 0x04 0x06 0x00 0x05 0x00
rxed att command: find info req; conn=0 start_handle=0x0006 end_handle=0x0005
txed att command: error rsp; conn=0 req_op=4 handle=0x0006 error_code=1
host tx hci data; handle=0 length=9
ble_hs_hci_acl_tx(): 0x00 0x00 0x09 0x00 0x05 0x00 0x04 0x00 0x01 0x04 0x06 0x00 0x01
Number of Completed Packets: num_handles=1
handle:0 pkts:1
ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=7 data=0x03 0x00 0x04 0x00 0x0a 0x03 0x00
rxed att command: read req; conn=0 handle=0x0003
host tx hci data; handle=0 length=19
ble_hs_hci_acl_tx(): 0x00 0x00 0x13 0x00 0x0f 0x00 0x04 0x00 0x0b 0x6e 0x69 0x6d 0x62 0x6c 0x65 0x2d 0x62 0x6c 0x65 0x70 0x72 0x70 0x68
Number of Completed Packets: num_handles=1
handle:0 pkts:1
ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=11 data=0x07 0x00 0x06 0x00 0x01 0x04 0x00 0x00 0x10 0x00 0x00
rxed sm command: pair req; conn=0 io_cap=4 oob_data_flag=0 authreq=0x00 mac_enc_key_size=16 init_key_dist=0 resp_key_dist=0
looking up peer sec;
looking up our sec;
looking up peer sec; peer_addr_type=1 peer_addr=0xe8 0xf9 0x5c 0x85 0x0c 0xfa
host tx hci data; handle=0 length=11
ble_hs_hci_acl_tx(): 0x00 0x00 0x0b 0x00 0x07 0x00 0x06 0x00 0x02 0x03 0x00 0x01 0x10 0x00 0x00
ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0018 len=0
0x18 0x20 0x00
Command complete: cmd_pkts=5 ogf=0x8 ocf=0x18 status=0 rand=0xb30ad58c80f1ee24
ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0018 len=0
0x18 0x20 0x00
Command complete: cmd_pkts=5 ogf=0x8 ocf=0x18 status=0 rand=0xcf36e6e84469d4e1
ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=21 data=0x11 0x00 0x06 0x00 0x03 0x17 0xde 0x4b 0x72 0xf4 0x9c 0x02 0xf1 0xe8 0x75 0xae 0x71 0x36 0x52 0xcc 0xcf
rxed sm command: confirm; conn=0 value=0x17 0xde 0x4b 0x72 0xf4 0x9c 0x02 0xf1 0xe8 0x75 0xae 0x71 0x36 0x52 0xcc 0xcf
ble_sm_alg_c1()
    k=0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
    r=0xb3 0x0a 0xd5 0x8c 0x80 0xf1 0xee 0x24 0xcf 0x36 0xe6 0xe8 0x44 0x69 0xd4 0xe1
    iat=1 rat=0
    ia=0xe8 0xf9 0x5c 0x85 0x0c 0xfa
    ra=0x22 0xfc 0xd4 0xc2 0xdd 0xbc
    preq=0x01 0x04 0x00 0x00 0x10 0x00 0x00
    pres=0x02 0x03 0x00 0x01 0x10 0x00 0x00
    p1=0x01 0x00 0x01 0x04 0x00 0x00 0x10 0x00 0x00 0x02 0x03 0x00 0x01 0x10 0x00 0x00
    p2=0x22 0xfc 0xd4 0xc2 0xdd 0xbc 0xe8 0xf9 0x5c 0x85 0x0c 0xfa 0x00 0x00 0x00 0x00
    out_enc_data=0x8c 0xd3 0x5d 0x50 0xa1 0x70 0xae 0x6c 0xcb 0x87 0xdc 0xa8 0x28 0x59 0x5a 0xe8
    rc=0
host tx hci data; handle=0 length=21
ble_hs_hci_acl_tx(): 0x00 0x00 0x15 0x00 0x11 0x00 0x06 0x00 0x03 0x8c 0xd3 0x5d 0x50 0xa1 0x70 0xae 0x6c 0xcb 0x87 0xdc 0xa8 0x28 0x59 0x5a 0xe8
Number of Completed Packets: num_handles=1
handle:0 pkts:1
Number of Completed Packets: num_handles=1
handle:0 pkts:1
ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=21 data=0x11 0x00 0x06 0x00 0x04 0x55 0x4c 0x70 0x52 0xd8 0x90 0x22 0x2a 0xca 0xd5 0xa3 0xf4 0x40 0xe9 0x48 0x75
rxed sm command: random; conn=0 value=0x55 0x4c 0x70 0x52 0xd8 0x90 0x22 0x2a 0xca 0xd5 0xa3 0xf4 0x40 0xe9 0x48 0x75
ble_sm_alg_c1()
    k=0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
    r=0x55 0x4c 0x70 0x52 0xd8 0x90 0x22 0x2a 0xca 0xd5 0xa3 0xf4 0x40 0xe9 0x48 0x75
    iat=1 rat=0
    ia=0xe8 0xf9 0x5c 0x85 0x0c 0xfa
    ra=0x22 0xfc 0xd4 0xc2 0xdd 0xbc
    preq=0x01 0x04 0x00 0x00 0x10 0x00 0x00
    pres=0x02 0x03 0x00 0x01 0x10 0x00 0x00
    p1=0x01 0x00 0x01 0x04 0x00 0x00 0x10 0x00 0x00 0x02 0x03 0x00 0x01 0x10 0x00 0x00
    p2=0x22 0xfc 0xd4 0xc2 0xdd 0xbc 0xe8 0xf9 0x5c 0x85 0x0c 0xfa 0x00 0x00 0x00 0x00
    out_enc_data=0x17 0xde 0x4b 0x72 0xf4 0x9c 0x02 0xf1 0xe8 0x75 0xae 0x71 0x36 0x52 0xcc 0xcf
    rc=0
ble_sm_alg_s1()
    k=0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
    r1=0xb3 0x0a 0xd5 0x8c 0x80 0xf1 0xee 0x24 0xcf 0x36 0xe6 0xe8 0x44 0x69 0xd4 0xe1
    r2=0x55 0x4c 0x70 0x52 0xd8 0x90 0x22 0x2a 0xca 0xd5 0xa3 0xf4 0x40 0xe9 0x48 0x75
    out=0xae 0xf6 0x3e 0x4c 0x90 0x77 0x03 0xd8 0x9d 0x36 0x44 0x98 0xe9 0x58 0x5b 0xd5
host tx hci data; handle=0 length=21
ble_hs_hci_acl_tx(): 0x00 0x00 0x15 0x00 0x11 0x00 0x06 0x00 0x04 0xb3 0x0a 0xd5 0x8c 0x80 0xf1 0xee 0x24 0xcf 0x36 0xe6 0xe8 0x44 0x69 0xd4 0xe1
Number of Completed Packets: num_handles=1
handle:0 pkts:1
LE LTK Req. handle=0 rand=00 encdiv=0
ble_hs_hci_cmd_send: ogf=0x08 ocf=0x001a len=18
0x1a 0x20 0x12 0x00 0x00 0xae 0xf6 0x3e 0x4c 0x90 0x77 0x03 0xd8 0x9d 0x36 0x44 0x98 0xe9 0x58 0x5b 0xd5
Command complete: cmd_pkts=5 ogf=0x8 ocf=0x1a status=0 handle=0
Encrypt change: status=0 handle=0 state=1
encryption change event; status=0 handle=0 our_ota_addr_type=0 our_ota_addr=bc:dd:c2:d4:fc:22 our_id_addr_type=0 our_id_addr=bc:dd:c2:d4:fc:22 peer_ota_addr_type=1 peer_ota_addr=fa:0c:85:5c:f9:e8 peer_id_addr_type=1 peer_id_addr=fa:0c:85:5c:f9:e8 conn_itvl=6 conn_latency=0 supervision_timeout=400 encrypted=1 authenticated=0 bonded=1

ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=11 data=0x07 0x00 0x04 0x00 0x08 0x06 0x00 0x09 0x00 0x03 0x28
rxed att command: read type req; conn=0 start_handle=0x0006 end_handle=0x0009
txed att command: read type rsp; conn=0 length=7
host tx hci data; handle=0 length=13
ble_hs_hci_acl_tx(): 0x00 0x00 0x0d 0x00 0x09 0x00 0x04 0x00 0x09 0x07 0x07 0x00 0x20 0x08 0x00 0x05 0x2a
Number of Completed Packets: num_handles=1
handle:0 pkts:1
ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=11 data=0x07 0x00 0x04 0x00 0x08 0x08 0x00 0x09 0x00 0x03 0x28
rxed att command: read type req; conn=0 start_handle=0x0008 end_handle=0x0009
txed att command: error rsp; conn=0 req_op=8 handle=0x0008 error_code=10
host tx hci data; handle=0 length=9
ble_hs_hci_acl_tx(): 0x00 0x00 0x09 0x00 0x05 0x00 0x04 0x00 0x01 0x08 0x08 0x00 0x0a
Number of Completed Packets: num_handles=1
handle:0 pkts:1
ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=9 data=0x05 0x00 0x04 0x00 0x04 0x09 0x00 0x09 0x00
rxed att command: find info req; conn=0 start_handle=0x0009 end_handle=0x0009
txed att command: find info rsp; conn=0 format=1
host tx hci data; handle=0 length=10
ble_hs_hci_acl_tx(): 0x00 0x00 0x0a 0x00 0x06 0x00 0x04 0x00 0x05 0x01 0x09 0x00 0x02 0x29
Number of Completed Packets: num_handles=1
handle:0 pkts:1
ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=7 data=0x03 0x00 0x04 0x00 0x0a 0x09 0x00
rxed att command: read req; conn=0 handle=0x0009
host tx hci data; handle=0 length=7
ble_hs_hci_acl_tx(): 0x00 0x00 0x07 0x00 0x03 0x00 0x04 0x00 0x0b 0x00 0x00
Number of Completed Packets: num_handles=1
handle:0 pkts:1
ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=9 data=0x05 0x00 0x04 0x00 0x12 0x09 0x00 0x02 0x00
rxed att command: write req; conn=0 handle=0x0009
subscribe event; conn_handle=0 attr_handle=8 reason=1 prevn=0 curn=0 previ=0 curi=1
error persisting cccd; too many entries (4)
looking up our sec;
error persisting cccd; too many entries (4)
looking up our sec;
error persisting cccd; too many entries (4)
looking up our sec;
error persisting cccd; too many entries (4)
looking up our sec;
error persisting cccd; too many entries (4)
looking up our sec;
error persisting cccd; too many entries (4)
looking up our sec;
error persisting cccd; too many entries (4)
looking up our sec;
error persisting cccd; too many entries (4)
looking up our sec;
error persisting cccd; too many entries (4)
looking up our sec;
error persisting cccd; too many entries (4)
looking up our sec;
error persisting cccd; too many entries (4)
looking up our sec;
error persisting cccd; too many entries (4)
looking up our sec;
error persisting cccd; too many entries (4)
looking up our sec;
error persisting cccd; too many entries (4)
looking up our sec;
error persisting cccd; too many entries (4)
looking up our sec;
error persisting cccd; too many entries (4)
looking up our sec;
error persisting cccd; too many entries (4)
looking up our sec;
error persisting cccd; too many entries (4)
looking up our sec;
error persisting cccd; too many entries (4)
looking upE (19992) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
E (19992) task_wdt:  - IDLE0 (CPU 0)
E (19992) task_wdt: Tasks currently running:
E (19992) task_wdt: CPU 0: ble
E (19992) task_wdt: CPU 1: IDLE1
 our sec;
error persisting cccd; too many entries (4)
looking up our sec;
error persisting cccd; too many entries (4)
looking up our sec;
error persisting cccd; too many entries (4)
looking up our sec;
error persisting cccd; too many entries (4)
looking up our sec;
... (will continue infinite)

Done

@albertmbt @Unsigus, @prasad-alatkar is looking into this and will update after there is progress. Thanks!