hfp_hf disconnects after a few seconds

[iamflimflam1]

I'm trying to run the esp-idf hfp_hf example

Code: Select all

examples/bluetooth/bluedroid/classic_bt/hfp_hf

It seems to work, but disconnects after a short period of time. This is what I see in the logs:

Code: Select all

hfp_hf> con
connect
W (6571) BT_APPL: HF Client found collision (ACL) ...
hfp_hf> I (14101) BT_HF: ESP_BT_GAP_DISC_STATE_CHANGED_EVT
W (20421) BT_RFCOMM: rfc_find_lcid_mcb LCID reused LCID:0x40 current:0x0
W (20421) BT_RFCOMM: RFCOMM_DisconnectInd LCID:0x40
I (66581) BT_HF: APP HFP event: CONNECTION_STATE_EVT
I (66581) BT_HF: --connection state disconnected, peer feats 0x0, chld_feats 0x0

This is connecting to a Mac computer. Any suggestions on how to get a stable connection or debug what is happening? Does anyone have a working example? My end goal is to setup the ESP32 as a bluetooth microphone and this seems to be the only way to do this.

I'm aware that the bandwidth is severely limited, but this is just for a proof of concept.

[iamflimflam1]

For anyone looking for a working hsp_hf I've pulled together something that works using: https://github.com/bluekitchen/btstack

It's very much based on their demo code with a very small amount of cleanup and addition of microphone input so it fully works.

https://github.com/atomic14/esp32-hsp-hf

[expresspotato]

Same problem here on IDF v4.3.1 pulled from master. Easy to reproduce, just fire up the HFP example and it always disconnects in about 10 seconds every single time...

Code: Select all

rst:0x1 (POWERON_RESET),boot:0x1f (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:1
load:0x3fff0030,len:7308
ho 0 tail 12 room 4
load:0x40078000,len:15328
load:0x40080400,len:4428
0x40080400: _init at ??:?

entry 0x400806a0
I (29) boot: ESP-IDF v4.3.1 2nd stage bootloader
I (29) boot: compile time 11:42:05
I (29) boot: chip revision: 3
I (32) qio_mode: Enabling default flash chip QIO
I (37) boot.esp32: SPI Speed      : 80MHz
I (42) boot.esp32: SPI Mode       : QIO
I (46) boot.esp32: SPI Flash Size : 8MB
I (51) boot: Enabling RNG early entropy source...
I (56) boot: Partition Table:
I (60) boot: ## Label            Usage          Type ST Offset   Length
I (67) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (75) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (82) boot:  2 factory          factory app      00 00 00010000 00200000
I (90) boot: End of partition table
I (94) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=16a34h ( 92724) map
I (128) esp_image: segment 1: paddr=00026a5c vaddr=3ffbdb60 size=03c68h ( 15464) load
I (133) esp_image: segment 2: paddr=0002a6cc vaddr=40080000 size=0594ch ( 22860) load
I (141) esp_image: segment 3: paddr=00030020 vaddr=400d0020 size=ab4a8h (701608) map
I (335) esp_image: segment 4: paddr=000db4d0 vaddr=4008594c size=13678h ( 79480) load
I (361) esp_image: segment 5: paddr=000eeb50 vaddr=50000200 size=00010h (    16) load
I (373) boot: Loaded app from partition at offset 0x10000
I (374) boot: Disabling RNG early entropy source...
I (385) psram: This chip is ESP32-D0WD
I (385) spiram: Found 64MBit SPI RAM device
I (385) spiram: SPI RAM mode: flash 80m sram 80m
I (388) spiram: PSRAM initialized, cache is in low/high (2-core) mode.
I (396) cpu_start: Pro cpu up.
I (399) cpu_start: Starting app cpu, entry point is 0x40081318
0x40081318: call_start_cpu1 at /home/kevin/esp-idf/components/esp_system/port/cpu_start.c:141

I (0) cpu_start: App cpu up.
I (893) spiram: SPI SRAM memory test OK
I (957) cpu_start: Pro cpu start user code
I (957) cpu_start: cpu freq: 80000000
I (957) cpu_start: Application information:
I (960) cpu_start: Project name:     liberty
I (965) cpu_start: App version:      27d8bd8-dirty
I (970) cpu_start: Compile time:     Nov 13 2021 11:42:01
I (976) cpu_start: ELF file SHA256:  8e536ef35b1881f8...
I (982) cpu_start: ESP-IDF:          v4.3.1
I (987) heap_init: Initializing. RAM available for dynamic allocation:
I (994) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (1000) heap_init: At 3FFB7CD8 len 00000328 (0 KiB): DRAM
I (1007) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (1013) heap_init: At 3FFC3188 len 0001CE78 (115 KiB): DRAM
I (1019) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1026) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1032) heap_init: At 40098FC4 len 0000703C (28 KiB): IRAM
I (1038) spiram: Adding pool of 4093K of external SPI memory to heap allocator
I (1047) spi_flash: detected chip: gd
I (1051) spi_flash: flash io: qio
I (1066) pm: Frequency switching config: CPU_MAX: 80, APB_MAX: 80, APB_MIN: 40, Light sleep: DISABLED
I (1067) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (1077) spiram: Reserving pool of 64K of internal memory for DMA/internal allocations
I (1087) LIBERTY: ******** LIBERTY MAIN START ********
I (1087) pm: Frequency switching config: CPU_MAX: 10, APB_MAX: 10, APB_MIN: 10, Light sleep: ENABLED
I (1137) LIBERTY: Start reason (booted)
I (1137) pm: Frequency switching config: CPU_MAX: 240, APB_MAX: 240, APB_MIN: 80, Light sleep: DISABLED
I (1137) BTDM_INIT: BT controller compile version [bfbbe1e]
I (1147) system_api: Base MAC address is not set
I (1147) system_api: read default base MAC address from EFUSE
I (1157) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
--> Event? 10I (2337) LIBERTY: event: 10
--> Event? 10I (2357) LIBERTY: event: 10
--> Event? 10I (2357) LIBERTY: event: 10
--> Event? 10I (2357) LIBERTY: event: 10
--> Event? 1I (2357) LIBERTY: ESP_BT_GAP_DISC_STATE_CHANGED_EVT
--> Event? 02
3
--> RSSI: -14
I (3397) LIBERTY: Found the target device address: 

I (3397) LIBERTY: c4 18 e9 6f bf fc 
I (3397) LIBERTY: Found the target device name: Kevin's S21
Connect.
--> Event? 1I (3407) LIBERTY: ESP_BT_GAP_DISC_STATE_CHANGED_EVT
E (4907) LIBERTY: APP HFP event: CONNECTION_STATE_EVT
E (4907) LIBERTY: --connection state connected, peer feats 0x0, chld_feats 0x0
W (4917) LIBERTY: Connected
E (5027) LIBERTY: APP HFP event: CALL_IND_EVT
E (5027) LIBERTY: --Call indicator NO call in progress
E (5027) LIBERTY: APP HFP event: CALL_SETUP_IND_EVT
E (5027) LIBERTY: --Call setup indicator NONE
E (5037) LIBERTY: APP HFP event: NETWORK_STATE_EVT
E (5037) LIBERTY: --NETWORK STATE available
E (5047) LIBERTY: APP HFP event: SIGNAL_STRENGTH_IND_EVT
E (5047) LIBERTY: -- signal strength: 0
E (5057) LIBERTY: APP HFP event: ROAMING_STATUS_IND_EVT
E (5057) LIBERTY: --ROAMING: inactive
E (5067) LIBERTY: APP HFP event: BATTERY_LEVEL_IND_EVT
E (5067) LIBERTY: --battery level 5
E (5077) LIBERTY: APP HFP event: CALL_HELD_IND_EVT
E (5077) LIBERTY: --Call held indicator NONE held
E (5087) LIBERTY: APP HFP event: CONNECTION_STATE_EVT
E (5087) LIBERTY: --connection state slc_connected, peer feats 0xfe7, chld_feats 0x3f
E (11187) LIBERTY: --> Event? 0
I (11187) LIBERTY: A2DP connection state: Connecting, [c4:18:e9:6f:bf:fc]
E (11207) LIBERTY: --> Event? 2
I (11207) LIBERTY: A2DP audio stream configuration, codec type 0
I (11207) LIBERTY: Bluetooth configured, sample rate=44100
E (11277) LIBERTY: --> Event? 0
I (11277) LIBERTY: A2DP connection state: Connected, [c4:18:e9:6f:bf:fc]
I (11277) LIBERTY: A2DP connection state = CONNECTED
I (11327) LIBERTY: ESP_AVRC_CT_CONNECTION_STATE_EVT
I (11327) LIBERTY: AVRC conn_state evt: state 1, [c4:18:e9:6f:bf:fc]
I (11327) LIBERTY: AVRC remote features 25b
--> Event? 13I (14487) LIBERTY: ESP_BT_GAP_MODE_CHG_EVT mode:2
E (18987) LIBERTY: --> Event? 0
I (18987) LIBERTY: A2DP connection state: Disconnected, [c4:18:e9:6f:bf:fc]
I (18987) LIBERTY: A2DP connection state =  DISCONNECTED
I (18997) LIBERTY: AVRC conn_state evt: state 0, [00:00:00:00:00:00]
E (18997) LIBERTY: APP HFP event: CONNECTION_STATE_EVT
E (19007) LIBERTY: --connection state disconnected, peer feats 0x0, chld_feats 0x0
W (19017) LIBERTY: Disconnected