HFP AG example error - connect_init: HF AG not initialized (IDFGH-9979)

[ypiotrp]

Answers checklist.

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

IDF version.

v5.0.1

Operating System used.

Windows

How did you build your project?

Command line with idf.py

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

PowerShell

Development Kit.

ESP32 Wroom DevKit

Power Supply used.

USB

What is the expected behavior?

I tried to run the HFP AG example. Unfortunately the Bluetooth Stack didn't get initialized properly and I was unable to connect to my headset and further test the example.

What is the actual behavior?

Failed to initialize the Bluetooth Stack (being more precise - connect_init: HF AG not initialized

Steps to reproduce.

1. Get the HFP AG example from ESP IDF 5.0.1.
2. Enter the menuconfig and change the following:

• Component config -> Bluetooth -> Bluedroid Options -> audio (SCO) data path -> HCI
• Component config -> Bluetooth -> Controller Options -> BR/EDR Sync (SCO/eSCO) default data path -> HCI

3. Change the MAC address of the headset you want to connect to in app_hf_msg_set.c:18
4. Build and run the example.
5. After booting up I saw the following error log:
   E (1316) BT_BTC: btc_hf_cb_handler: Invalid index 31883
6. Try to connect to your headset using con command.

Debug Logs.

Executing action: monitor
Running idf_monitor in directory c:\projects\hfp_ag_esp_5.0.1
Executing "C:\Users\partyka\.espressif\python_env\idf5.0_py3.10_env\Scripts\python.exe C:\projects\esp-idf-v5.0.1\tools/idf_monitor.py -p COM4 -b 115200 --toolchain-prefix xtensa-esp32-elf- --target esp32 --revision 0 c:\projects\hfp_ag_esp_5.0.1\build\hfp_ag.elf --force-color -m 'C:\Users\partyka\.espressif\python_env\idf5.0_py3.10_env\Scripts\python.exe' 'C:\projects\esp-idf-v5.0.1\tools\idf.py' '-p' 'COM4'"...
--- WARNING: GDB cannot open serial ports accessed as COMx
--- Using \\.\COM4 instead...
--- idf_monitor on \\.\COM4 115200 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:6940
ho 0 tail 12 room 4
load:0x40078000,len:15500
load:0x40080400,len:3844
0x40080400: _init at ??:?

entry 0x4008064c
I (28) boot: ESP-IDF v5.0.1 2nd stage bootloader
I (29) boot: compile time 14:04:38
I (29) boot: chip revision: v1.0
I (31) boot.esp32: SPI Speed      : 40MHz
I (36) boot.esp32: SPI Mode       : DIO
I (41) boot.esp32: SPI Flash Size : 2MB
I (45) boot: Enabling RNG early entropy source...
I (51) boot: Partition Table:
I (54) boot: ## Label            Usage          Type ST Offset   Length
I (61) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (69) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (76) boot:  2 factory          factory app      00 00 00010000 00100000
I (84) boot: End of partition table
I (88) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=1e928h (125224) map
I (142) esp_image: segment 1: paddr=0002e950 vaddr=3ffbdb60 size=016c8h (  5832) load
I (144) esp_image: segment 2: paddr=00030020 vaddr=400d0020 size=7c760h (509792) map
I (332) esp_image: segment 3: paddr=000ac788 vaddr=3ffbf228 size=02c94h ( 11412) load
I (336) esp_image: segment 4: paddr=000af424 vaddr=40080000 size=18858h (100440) load
I (391) boot: Loaded app from partition at offset 0x10000
I (391) boot: Disabling RNG early entropy source...
I (403) cpu_start: Pro cpu up.
I (403) cpu_start: Starting app cpu, entry point is 0x400813d0
0x400813d0: call_start_cpu1 at C:/projects/esp-idf-v5.0.1/components/esp_system/port/cpu_start.c:142

I (0) cpu_start: App cpu up.
I (419) cpu_start: Pro cpu start user code
I (419) cpu_start: cpu freq: 160000000 Hz
I (419) cpu_start: Application information:
I (424) cpu_start: Project name:     hfp_ag
I (429) cpu_start: App version:      1
I (433) cpu_start: Compile time:     Apr 21 2023 14:31:43
I (439) cpu_start: ELF file SHA256:  40dbeb100f309e93...
I (445) cpu_start: ESP-IDF:          v5.0.1
I (450) cpu_start: Min chip rev:     v0.0
I (455) cpu_start: Max chip rev:     v3.99
I (460) cpu_start: Chip rev:         v1.0
I (465) heap_init: Initializing. RAM available for dynamic allocation:
I (472) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (478) heap_init: At 3FFB6BF8 len 00001408 (5 KiB): DRAM
I (484) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (490) heap_init: At 3FFC7C88 len 00018378 (96 KiB): DRAM
I (496) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (503) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (509) heap_init: At 40098858 len 000077A8 (29 KiB): IRAM
I (517) spi_flash: detected chip: generic
I (520) spi_flash: flash io: dio
W (524) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (538) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (588) BTDM_INIT: BT controller compile version [60aae55]
I (598) system_api: Base MAC address is not set
I (598) system_api: read default base MAC address from EFUSE
I (598) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
W (1258) BT_BTC: btc_hf_cb_handler: event = BTA_AG_ENABLE_EVT
E (1268) BT_BTC: btc_hf_cb_handler: Invalid index 31899
W (1268) BT_BTC: btc_hf_cb_handler: event = BTA_AG_REGISTER_EVT
I (1278) gpio: GPIO[19]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (1288) gpio: GPIO[21]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (1298) gpio: GPIO[22]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
 ==================================================
 |       Steps to test hfp_ag                     |
 |                                                |
 |  1. Print 'help' to gain overview of commands  |
 |  2. Setup a service level connection           |
 |  3. Run hfp_ag to test                         |
 |                                                |
 =================================================


Type 'help' to get the list of commands.
Use UP/DOWN arrows to navigate through command history.
Press TAB when typing command name to auto-complete.
hfp_ag> con
Connect.
W (5738) BT_BTIF: CHECK_HF_INIT: connect_init: HF AG not initialized
hfp_ag>

More Information.

No response

[xiongweichao]

Hi @ypiotrp ,

This commit fixes this issue.

Thanks

[ypiotrp]

Hi @xiongweichao,
Thank you for your reply. I cherry-picked this commit and it indeed helped with this issue.

Unfortunately the error message still persists. First it shows up after startup - as you can see the timestamp of the log is rather small:
E (1259) BT_BTC: btc_hf_cb_handler: Invalid index 31883
Then after I connect to my headset it shows again but with different index:
E (11280) BT_BTC: btc_hf_cb_handler: Invalid index 21796
Could you explain why it happens?

[xiongweichao]

Hi @ypiotrp ,

This error occurs because this parameter is modified into a variable-length array. But I don't think this will affect the use. If there are other problems, please help to print this event.

Thanks

[ypiotrp]

Hi @xiongweichao,
Thank you for your reply. I added event to error logs I mentioned and they present as follows:

1. After the startup - E (1290) BT_BTC: btc_hf_cb_handler: Invalid index 31899; event = BTA_AG_ENABLE_EVT
2. After connection - E (7480) BT_BTC: btc_hf_cb_handler: Invalid index 21812; event = BTA_AG_WBS_EVT

[xiongweichao]

Hi @ypiotrp , Please try this patch.
fix_idx_invalid.txt