Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Task watchdog got triggered in BLE functions (IDFGH-2271) #4413

Closed
ildus opened this issue Nov 27, 2019 · 27 comments
Closed

Task watchdog got triggered in BLE functions (IDFGH-2271) #4413

ildus opened this issue Nov 27, 2019 · 27 comments

Comments

@ildus
Copy link

ildus commented Nov 27, 2019

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.

@github-actions github-actions bot changed the title Task watchdog got triggered in BLE functions Task watchdog got triggered in BLE functions (IDFGH-2271) Nov 27, 2019
@prasad-alatkar
Copy link
Contributor

Hi @ildus Could you please let me know if you have made any changes to default bleprph example ? Just FYI, I have fixed an issue in NimBLE porting layer which is in internal pipeline that maybe relevant here, I will notify you as soon as it is available on github.

@ildus
Copy link
Author

ildus commented Nov 28, 2019

I get this error on default bleprph too. Strange thing, when I just started everything was ok for a while.

@prasad-alatkar
Copy link
Contributor

@ildus fix for NimBLE porting layer is available on github master, commit id : 656005e. Can you please check the issue with the latest master ?

@Alvin1Zhang
Copy link
Collaborator

@ildus Thanks for reporting. Would you please help check whether your issue has been fixed with the latest master? Thanks.

@ildus
Copy link
Author

ildus commented Jan 7, 2020

@Alvin1Zhang @prasad-alatkar sorry, will test today evening (about 20:00 UTC).

@ildus
Copy link
Author

ildus commented Jan 7, 2020

Ok, just checked. The problem seems to be gone. Thank you.

@ildus ildus closed this as completed Jan 7, 2020
@albertmbt
Copy link

albertmbt commented Mar 11, 2020

Hi there,

I still have this same issue with stable version 4.0. and working over the bleprph example with no modifications. (I actually tested also with the master branch getting same results).

At the first, I started working with no issues, but after a while it started with watchdog error just after a subscribe event. Then this error log keeps going every 5 seconds forever.

subscribe event; conn_handle=0 attr_handle=8 reason=1 prevn=0 curn=0 previ=0 curi=1

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

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

...

I tried flashing it to a new module, and it is working properly for now, bit I think it's about time. In fact, there is no way that my first module can get it to work having the same code.

Maybe I lost something?

@prasad-alatkar
Copy link
Contributor

Hi @albertmbt Can you try erase_flash on the module and flash again ? If you still face the issue, can you please share debug logs(make menuconfig -->component config-->Log output-->Default log verbosity-->Debug) ?

@albertmbt
Copy link

albertmbt commented Mar 12, 2020

Yep erasing memory solves the problem. I wasn't paying attention when I first got the error, probably it's a problem after flash then and not randomly on work as I thought.

I mean, if it gets stuck after a while on working having to erase flash every time it's a problem.

@prasad-alatkar
Copy link
Contributor

Hi @albertmbt I understand, please provide debug logs if you get this issue again.

@ildus ildus reopened this Mar 14, 2020
@Alvin1Zhang
Copy link
Collaborator

@ildus Thanks for reopening. Did you run into the issue again? Could you please help share any updates or details? Thanks.

@Unsigus
Copy link

Unsigus commented Mar 17, 2020

Hi, I also got into this problem. It happens when there are too many cccd's stored in NVS. I can force this behavior enabling notification for a characteristic.

Here is the verbose debug log from the bleprph example:

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 (8)
looking up our sec;
error persisting cccd; too many entries (8)
looking up our sec;
error persisting cccd; too many entries (8)
looking up our sec;
error persisting cccd; too many entries (8)
looking up our sec;
.... (infinite)

@Unsigus
Copy link

Unsigus commented Mar 18, 2020

@albertmbt or @Alvin1Zhang
The issue occours in the ble_store_write() in ble_store.c. The loop expects after calling ble_store_overflow_event(), that there is room available. Somehow this isn't the case.

I'm too unfamiliar with the IDF to further investigate the issue, I hope you can solve it. Thanks!

@dhrishi
Copy link
Collaborator

dhrishi commented Mar 18, 2020

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

@prasad-alatkar
Copy link
Contributor

Hi @Unsigus this is actually not the same issue.
For your case, I am afraid but you have to increase CCCDs from menuconfig (make menuconfig --> Component config--> Bluetooth--> NimBLE Options--> Maximum number of CCC descriptors to save across reboots).

The issue occours in the ble_store_write() in ble_store.c. The loop expects after calling ble_store_overflow_event(), that there is room available. Somehow this isn't the case.

Yes, NimBLE stack makes space by deleting oldest peer ble_gap_unpair_oldest_peer. However for your case if application needs more than 8 CCDs per device then the application should configure it beforehand.

Please let me know if you find any other issue. Please help to close the issue if you find the response satisfactory.

@Unsigus
Copy link

Unsigus commented Mar 18, 2020

Hi @prasad-alatkar, Thank you for your time, and will tweak my settings.
But don't you agree that the app needs to respond differently (like an assert) than getting into an infinite loop (thus a watchdog timeout)? That can save a lot of time when others run into this problem.

@prasad-alatkar
Copy link
Contributor

@Unsigus Could you please update if your issue was resolved with tweaking settings from menuconfig ?

But don't you agree that the app needs to respond differently (like an assert) than getting into an infinite loop (thus a watchdog timeout)? That can save a lot of time when others run into this problem.

I do agree that there should be better way to handle this. However it is application developer's responsibility as well to configure minimum required settings. Having said that I am also thinking about proper handling of this particulate situation, will update you accordingly.

Apart from that just to maintain history of the issue clean, the issue @Unsigus has faced is different from the original reported issue which is infrequent and make erase_flash happened to resolve it. @albertmbt @ildus DId you guys get a chance to reproduce the issue with DEBUG logs on ?

@Unsigus
Copy link

Unsigus commented Mar 20, 2020

@prasad-alatkar, from my point of view the issue is the same. I also got this message every x seconds, while the app stops responding to everything else:

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

Using make erase_flash did solve that for some time. When the cccd NVS reaches is maximum (Don't now how that happens, my application doesn't need more than 8 cccd's per device. But I think it did not clear the records correctly when I was developing with trial and errors, clearing nvs did solve that)

With that information I've reproduced the issue that I think @albertmbt has. With the DEBUG log on this was printed directly when turning on notifications:

Here is the verbose debug log from the bleprph example:

rxed att command: find info req; conn=0 start_handle=0x0009 end_handle=0x0009
...
error persisting cccd; too many entries (8)
looking up our sec;
...

Changing Maximum number of CCC descriptors to save across reboots will solve the issue, but that's just a workaround in my opinion (the wrongly stored cccd's are still stored and will never be removed)

If this still not the same issue in your opinion, please inform me and I will leave you guys alone.

@albertmbt
Copy link

Hi guys, i've been busy on other project those days and i haven't been able to keep looking at it. i expect to have time during the next week. In the poor test's that i've made those days i haven't been able to reproduce the issue again. i'll keep updating.

@ildus
Copy link
Author

ildus commented Mar 20, 2020

@prasad-alatkar I just used old bluetooth stack for my device, and for now I'm not able to debug. But I remember in my case that the issue also was fixed after erasing the flash. But I agree with @Unsigus that is a bug, since it happens without any extra changes on example application, for example I didn't even know that there are some cccd's that are stored to flash. At least it should be logged, and there should be proper workaround.

@prasad-alatkar
Copy link
Contributor

Hi @Unsigus Could you please share the entire debug log ?

@Unsigus
Copy link

Unsigus commented Mar 20, 2020

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

@prasad-alatkar
Copy link
Contributor

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

@Unsigus
Copy link

Unsigus commented Apr 1, 2020

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.

@prasad-alatkar
Copy link
Contributor

@Unsigus Try to reduce number of CCCDs from menuconfig to reproduce this issue, make menuconfig --> Component config → Bluetooth → NimBLE Options --> Maximum number of CCC descriptors to save across reboots .

Apart from this just want to correct my earlier comment

if application needs more than 8 CCDs per device ...

The CCCDs configured are total CCCDs and not per device.

@prasad-alatkar
Copy link
Contributor

Hi @Unsigus The fix for this issue has been merged in mainstream esp-idf(Ref. commit: 2ef4890).

mahavirj pushed a commit to mahavirj/esp-afr-sdk that referenced this issue Jun 1, 2020
… (backport v3.3)

Change list:
- Reduces the size of the compiled binary, PR: espressif/esp-nimble#6
- Null pointer check, PR: apache/mynewt-nimble#701
- Pairing procedure abort on unexpected req: apache/mynewt-nimble#710
- Fix conn flags after pairing: apache/mynewt-nimble#730
- Remove notification for update process timeout (Vol 6, Part B, section 5.2 ):
  apache/mynewt-nimble#782
- CCCD fix : apache/mynewt-nimble#790 and
  apache/mynewt-nimble#804
- Host based Privacy (RPA) fix: espressif/esp-nimble#7

 Closes espressif/esp-nimble#10

 Closes espressif/esp-idf#4413
espressif-bot pushed a commit that referenced this issue Jun 15, 2020
… (backport v4.0)

Change list:
- Reduces the size of the compiled binary, PR: espressif/esp-nimble#6
- Null pointer check, PR: apache/mynewt-nimble#701
- Pairing procedure abort on unexpected req: apache/mynewt-nimble#710
- Fix conn flags after pairing: apache/mynewt-nimble#730
- Remove notification for update process timeout (Vol 6, Part B, section 5.2 ):
  apache/mynewt-nimble#782
- CCCD fix : apache/mynewt-nimble#790 and
  apache/mynewt-nimble#804
- Host based Privacy (RPA) fix: espressif/esp-nimble#7

 Closes espressif/esp-nimble#10

 Closes #4413
projectgus pushed a commit that referenced this issue Jul 22, 2020
… (backport v4.1)

Change list:
- Reduces the size of the compiled binary, PR: espressif/esp-nimble#6
- Null pointer check, PR: apache/mynewt-nimble#701
- Pairing procedure abort on unexpected req: apache/mynewt-nimble#710
- Fix conn flags after pairing: apache/mynewt-nimble#730
- Remove notification for update process timeout (Vol 6, Part B, section 5.2 ):
  apache/mynewt-nimble#782
- CCCD fix : apache/mynewt-nimble#790 and
  apache/mynewt-nimble#804
- Host based Privacy (RPA) fix: espressif/esp-nimble#7

 Closes espressif/esp-nimble#10

 Closes #4413
@ZweiEuro
Copy link

ZweiEuro commented Feb 23, 2021

Hi
I know I am a little late to the issue, but I get the same behavior after incorporating:
https://github.com/espressif/esp-idf/tree/master/examples/bluetooth/bluedroid/ble/gatt_server
into my project.

I ma not using Nimble though, so should I open a new issue for this ?
The error itself seems to be the same.

E (20458) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
E (20458) task_wdt:  - IDLE0 (CPU 0)
E (20458) task_wdt: Tasks currently running:
E (20458) task_wdt: CPU 0: btController
E (20458) task_wdt: CPU 1: IDLE1
E (20458) task_wdt: Print CPU 0 (current core) backtrace


Backtrace:0x401383FB:0x3FFBE8C0 0x40082E71:0x3FFBE8E0 0x40185A7D:0x3FFB5E90 0x4018602D:0x3FFB5EB0 0x4008FED5:0x3FFB5EE0 

E (20458) task_wdt: Print CPU 1 backtrace


Backtrace:0x40081DC3:0x3FFBEEC0 0x40082E71:0x3FFBEEE0 0x4000BFED:0x3FFBC870 0x40090135:0x3FFBC880 0x4013869F:0x3FFBC8A0 0x401386AB:0x3FFBC8D0 0x40138761:0x3FFBC8F0 0x40090B0D:0x3FFBC910 0x4008FED5:0x3FFBC930 

E (25458) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
E (25458) task_wdt:  - IDLE0 (CPU 0)
E (25458) task_wdt: Tasks currently running:
E (25458) task_wdt: CPU 0: btController
E (25458) task_wdt: CPU 1: IDLE1
E (25458) task_wdt: Print CPU 0 (current core) backtrace


Backtrace:0x401383FB:0x3FFBE8C0 0x40082E71:0x3FFBE8E0 0x40185A7D:0x3FFB5E90 0x4018602D:0x3FFB5EB0 0x4008FED5:0x3FFB5EE0 

E (25458) task_wdt: Print CPU 1 backtrace


Backtrace:0x40081DC3:0x3FFBEEC0 0x40082E71:0x3FFBEEE0 0x4000BFED:0x3FFBC870 0x40090135:0x3FFBC880 0x4013869F:0x3FFBC8A0 0x401386AB:0x3FFBC8D0 0x40138761:0x3FFBC8F0 0x40090B0D:0x3FFBC910 0x4008FED5:0x3FFBC930 

E (30458) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
E (30458) task_wdt:  - IDLE0 (CPU 0)
E (30458) task_wdt: Tasks currently running:
E (30458) task_wdt: CPU 0: btController
E (30458) task_wdt: CPU 1: IDLE1
E (30458) task_wdt: Print CPU 0 (current core) backtrace


Backtrace:0x401383FB:0x3FFBE8C0 0x40082E71:0x3FFBE8E0 0x40185A7D:0x3FFB5E90 0x4018602D:0x3FFB5EB0 0x4008FED5:0x3FFB5EE0 

E (30458) task_wdt: Print CPU 1 backtrace


Backtrace:0x40081DC3:0x3FFBEEC0 0x40082E71:0x3FFBEEE0 0x4000BFED:0x3FFBC870 0x40090135:0x3FFBC880 0x4013869F:0x3FFBC8A0 0x401386AB:0x3FFBC8D0 0x40138761:0x3FFBC8F0 0x40090B0D:0x3FFBC910 0x4008FED5:0x3FFBC930 

erasing the flash did not help.

After getting the above error, I get this:

ASSERT_PARAM(-218959118 0), in arch_main.c at line 343
Guru Meditation Error: Core  0 panic'ed (Interrupt wdt timeout on CPU0). 

Core  0 register dump:
PC      : 0x40084c5d  PS      : 0x00060e34  A0      : 0x8018563c  A1      : 0x3ffbe7b0  
A2      : 0x00000001  A3      : 0x00000000  A4      : 0x60008048  A5      : 0x00000000  
A6      : 0x00000004  A7      : 0x3ffbdbe4  A8      : 0x80084c58  A9      : 0x3ffbe790  
A10     : 0x00000000  A11     : 0x00000037  A12     : 0x00000014  A13     : 0xffffffff  
A14     : 0x00000000  A15     : 0xfffffffc  SAR     : 0x00000004  EXCCAUSE: 0x00000005  
EXCVADDR: 0x00000000  LBEG    : 0x40084b90  LEND    : 0x40084b97  LCOUNT  : 0x00000000  
Core  0 was running in ISR context:
EPC1    : 0x401ecc0f  EPC2    : 0x00000000  EPC3    : 0x00000000  EPC4    : 0x40084c5d

Backtrace:0x40084c5a:0x3ffbe7b0 0x40185639:0x3ffbe7d0 0x40019fb5:0x3ffbe7f0 0x4008935e:0x3ffbe820 0x40087ce1:0x3ffbe860 0x400879fd:0x3ffbe880 0x4008a0ea:0x3ffbe8a0 0x4008b1db:0x3ffbe8c0 0x40082e71:0x3ffbe8e0 0x40185a60:0x3ffb5e90 0x40186015:0x3ffb5eb0 0x4008fed5:0x3ffb5ee0
  #0  0x40084c5a:0x3ffbe7b0 in r_assert_param at ??:?
  #1  0x40185639:0x3ffbe7d0 in r_platform_reset at ??:?
  #2  0x40019fb5:0x3ffbe7f0 in ?? ??:0
  #3  0x4008935e:0x3ffbe820 in r_lld_pdu_rx_handler at ??:?
  #4  0x40087ce1:0x3ffbe860 in r_lld_evt_end at ??:?
  #5  0x400879fd:0x3ffbe880 in r_lld_evt_end_isr at ??:?
  #6  0x4008a0ea:0x3ffbe8a0 in r_rwble_isr at ??:?
  #7  0x4008b1db:0x3ffbe8c0 in r_rwbtdm_isr_wrapper at intc.c:?
  #8  0x40082e71:0x3ffbe8e0 in _xt_lowint1 at /home/zweieuro/.platformio/packages/framework-espidf/components/freertos/xtensa/xtensa_vectors.S:1105
  #9  0x40185a60:0x3ffb5e90 in r_rw_schedule at ??:?
  #10 0x40186015:0x3ffb5eb0 in btdm_controller_task at ??:?
  #11 0x4008fed5:0x3ffb5ee0 in vPortTaskWrapper at /home/zweieuro/.platformio/packages/framework-espidf/components/freertos/xtensa/port.c:143
Core  1 register dump:
PC      : 0x401eaea2  PS      : 0x00060534  A0      : 0x8013875d  A1      : 0x3ffbc8d0  
A2      : 0x00000000  A3      : 0x00000000  A4      : 0x00000001  A5      : 0x80000001  
A6      : 0x00000003  A7      : 0x00060023  A8      : 0x80138696  A9      : 0x3ffbc8a0  
A10     : 0x00000000  A11     : 0x00060023  A12     : 0x00060020  A13     : 0x00060023  
A14     : 0x00000001  A15     : 0x00000000  SAR     : 0x00000000  EXCCAUSE: 0x00000005  
EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000  

Backtrace:0x401eae9f:0x3ffbc8d0 0x4013875a:0x3ffbc8f0 0x40090b0d:0x3ffbc910 0x4008fed5:0x3ffbc930
  #0  0x401eae9f:0x3ffbc8d0 in esp_pm_impl_waiti at /home/zweieuro/.platformio/packages/framework-espidf/components/esp32/pm_esp32.c:484
  #1  0x4013875a:0x3ffbc8f0 in esp_vApplicationIdleHook at /home/zweieuro/.platformio/packages/framework-espidf/components/esp_common/src/freertos_hooks.c:63
  #2  0x40090b0d:0x3ffbc910 in prvIdleTask at /home/zweieuro/.platformio/packages/framework-espidf/components/freertos/tasks.c:3386 (discriminator 1)
  #3  0x4008fed5:0x3ffbc930 in vPortTaskWrapper at /home/zweieuro/.platformio/packages/framework-espidf/components/freertos/xtensa/port.c:143

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

7 participants