ESP32: Unable to connect to handsfree [hsp_ag_demo] & [hfp_ag_demo]

[yamiyukiharu]

Hi, I realized that I am unable to connect to my handsfree using either HFP or HSP. They both give the same error : "Service not found, status 129". Below is the console log for your reference.

Connect to 30:21:98:00:40:CC
[00:10:04.450] LOG -- hsp_ag.c.472: Start SDP query 30:21:98:00:40:CC, 0x1108
[00:10:04.450] LOG -- l2cap.c.1684: L2CAP_CREATE_CHANNEL addr 30:21:98:00:40:CC psm 0x1 mtu 1691 -> local mtu 1691
[00:10:04.458] LOG -- l2cap.c.1706: l2cap_create_channel, hci connection already exists
[00:10:04.466] LOG -- l2cap.c.1594: l2cap_handle_connection_complete expected state
[00:10:04.473] LOG -- l2cap.c.1622: l2cap received remote supported features, sec_level_0_allowed for psm 1 = 1
[00:10:04.483] ACL => 81 00 0C 00 08 00 01 00 02 03 04 00 01 00 42 00
[00:10:04.489] LOG -- l2cap.c.963: l2cap_stop_rtx for local cid 0x42
[00:10:04.495] LOG -- l2cap.c.969: l2cap_start_rtx for local cid 0x42
[00:10:04.502] EVT <= 6E 00
[00:10:04.504] EVT <= 13 05 01 81 00 01 00
[00:10:04.521] ACL <= 81 20 10 00 0C 00 01 00 03 03 08 00 46 00 42 00 00 00 00 00
[00:10:04.522] LOG -- l2cap.c.2275: L2CAP signaling handler code 3, state 10
[00:10:04.525] LOG -- l2cap.c.963: l2cap_stop_rtx for local cid 0x42
[00:10:04.531] ACL => 81 00 10 00 0C 00 01 00 04 04 08 00 46 00 00 00 01 02 9B 06
[00:10:04.538] LOG -- l2cap.c.963: l2cap_stop_rtx for local cid 0x42
[00:10:04.544] LOG -- l2cap.c.969: l2cap_start_rtx for local cid 0x42
[00:10:04.550] EVT <= 13 05 01 81 00 01 00
[00:10:04.554] EVT <= 6E 00
[00:10:04.569] ACL <= 81 20 11 00 0E 00 01 00 05 04 0A 00 42 00 00 00 00 00 01 02 A0
[00:10:04.572] ACL <= 81 10 01 00 02
[00:10:04.573] LOG -- l2cap.c.2275: L2CAP signaling handler code 5, state 11
[00:10:04.577] LOG -- l2cap.c.963: l2cap_stop_rtx for local cid 0x42
[00:10:04.583] LOG -- l2cap.c.2209: l2cap_signaling_handle_configure_response
[00:10:04.590] ACL <= 81 20 10 00 0C 00 01 00 04 0E 08 00 42 00 00 00 01 02 A0 02
[00:10:04.597] LOG -- l2cap.c.2275: L2CAP signaling handler code 4, state 11
[00:10:04.604] LOG -- l2cap.c.2140: Remote MTU 672
[00:10:04.608] ACL => 81 00 12 00 0E 00 01 00 05 0E 0A 00 46 00 00 00 00 00 01 02 9B 06
[00:10:04.616] LOG -- l2cap.c.838: L2CAP_EVENT_CHANNEL_OPENED status 0x0 addr 30:21:98:00:40:CC handle 0x81 psm 0x1 local_cid 0x42 remote_cid 0x46 local_mtu 1691, remote_mtu 672, flush_timeout 0
[00:10:04.633] EVT <= 70 16 00 CC 40 00 98 21 30 81 00 01 00 42 00 46 00 9B 06 A0 02 00 00 00
[00:10:04.641] EVT <= 13 05 01 81 00 01 00
[00:10:04.645] EVT <= 6E 00
[00:10:04.648] EVT <= 78 02 42 00
[00:10:04.651] ACL => 81 00 18 00 14 00 46 00 06 00 02 00 0F 35 03 19 11 08 06 9B 35 05 0A 00 01 01 00 00
[00:10:04.660] ACL <= 81 20 0C 00 08 00 01 00 06 0F 04 00 42 00 46 00
[00:10:04.667] LOG -- l2cap.c.2275: L2CAP signaling handler code 6, state 12
[00:10:04.673] EVT <= 13 05 01 81 00 01 00
[00:10:04.677] EVT <= 6E 00
[00:10:04.680] ACL => 81 00 0C 00 08 00 01 00 07 0F 04 00 42 00 46 00
[00:10:04.686] LOG -- l2cap.c.857: L2CAP_EVENT_CHANNEL_CLOSED local_cid 0x42
[00:10:04.693] EVT <= 71 02 42 00
[00:10:04.696] LOG -- sdp_client.c.478: SDP Client disconnected.
[00:10:04.702] LOG -- hsp_ag.c.728: Service not found, status 129.

Audio connection establishment failed with status 129
[00:10:04.713] LOG -- l2cap.c.963: l2cap_stop_rtx for local cid 0x42
[00:10:04.719] EVT <= 13 05 01 81 00 01 00
[00:10:04.723] EVT <= 6E 00
[00:10:04.744] ACL <= 81 20 11 00 4A 00 42 00 07 00 02 00 45 00 40 36 00 46 36 00 43
[00:10:04.747] ACL <= 81 10 11 00 09 00 01 35 06 19 11 08 19 12 03 09 00 04 35 0C 35
[00:10:04.749] ACL <= 81 10 11 00 03 19 01 00 35 05 19 00 03 08 02 09 00 06 35 09 09
[00:10:04.756] ACL <= 81 10 11 00 65 6E 09 00 6A 09 01 00 09 00 09 35 08 35 06 19 11
[00:10:04.763] ACL <= 81 10 0A 00 08 09 01 02 09 01 00 02 00 40

Thanks for taking your time to read this.

[mringwal]

hi! in the log, your handsfree unit disconnects the SDP connection right after BTstack sends the last configure response. Looking at this closely, BTstack did sent an incorrect value. I don't know if this causes the disconnect, but it could be.

I've fixed this incorrect value on the 'develop' branch. Could you switch to the develop branch, git pull, ./integrate_btstack.sh and try again?

unrelated: we didn't try SCO packets (used for HFP/HSP) yet, let see how this turns out. What do you want to do if you could send/receive audio data?

[yamiyukiharu]

Hi Matthias,

It connected like a charm using the develop branch btstack! I have tested the call simulation and it works, however it fails to establish an audio connection. Below is the log :

[00:04:51.858] LOG -- hfp_ag_demo.c.193: USER:'b'
Establish Audio connection 30:21:98:00:40:CC...
[00:04:51.858] LOG -- hfp_ag.c.2118: hfp_ag_setup_audio_connection state 24
[00:04:51.862] LOG -- hfp_ag.c.2124: hfp_ag_establish_audio_connection - no codec negotiation feature, using CVSD
[00:04:51.872] LOG -- hfp_ag.c.541: hfp_init_link_settings: 4
[00:04:51.878] LOG -- hfp.c.1440: hfp_setup_synchronous_connection using setting nr 4
[00:04:51.886] CMD => 28 04 11 80 00 40 1F 00 00 40 1F 00 00 0A 00 60 00 01 80 03
[00:04:51.893] EVT <= 6E 00
[00:04:51.895] EVT <= 78 02 41 00
[00:04:51.898] EVT <= 89 02 01 00
[00:04:51.902] EVT <= 78 02 41 00
[00:04:51.905] EVT <= 0F 04 1A 05 28 04
[00:04:51.908] LOG -- hfp.c.499: (e)SCO Connection failed status 0x1a

I am trying to make a bluetooth audio gateway between a walkie talkie module (VHF band) and a regular bluetooth headset. using the esp32 and an external audio codec which will send communicate with the esp32 via I2S. Because I need 2 way audio communication, the only profile that works for me is HFP/HSP. Please feel free to give suggestions on any better way to achieve this.

[yamiyukiharu]

Just to add on, I was using the hfp_ag_demo in the previous post. I tried out hsp_ag_demo subsequently and was able to establish an audio connection, but I dont hear anything from the headset, instead I get the following :

Establish audio connection
[00:08:57.027] CMD => 28 04 11 80 00 40 1F 00 00 40 1F 00 00 FF FF 60 00 FF 3F 00
[00:08:57.028] EVT <= 6E 00
[00:08:57.028] EVT <= 0F 04 00 05 28 04
[00:08:57.035] EVT <= 1B 03 80 00 01
[00:08:57.050] EVT <= 2C 11 00 80 01 CC 40 00 98 21 30 02 06 04 1E 00 1E 00 02
[00:08:57.051] LOG -- hci.c.1947: Synchronous Connection Complete (status=0) 30:21:98:00:40:CC
[00:08:57.055] LOG -- hci.c.184: create_connection_for_addr 30:21:98:00:40:CC, type fe
[00:08:57.063] LOG -- hsp_ag.c.625: eSCO Connection established.
[00:08:57.068] LOG -- hsp_ag.c.633: sco_handle 0x180, address 30:21:98:00:40:CC, transmission_interval 6 slots, retransmission_interval 4 slots, rx_packet_length 30 bytes, tx_packet_length 30 bytes, air_mode 0x 2 (0x02 == CVSD)
Audio connection established with SCO handle 0x0180.
[00:08:57.093] EVT <= 6F 00
[00:08:57.096] SCO => 80 01 30 00 00 0B 10 D5 1F 1E 2F AA 3D 3C 4B 9F 57 9F 62 12 6C D0 73 BB 79 BB 7D BE 7F BE 7F BB 7D BB 79 D0 73 12 6C 9F 62 9F 57 3C 4B AA 3D 1E 2F D5 1F
[00:08:57.111] EVT <= 6E 00
[00:08:57.114] EVT <= 6F 00
[00:08:57.116] SCO => 80 01 30 0B 10 00 00 F5 EF 2B E0 E2 D0 56 C2 C4 B4 61 A8 61 9D EE 93 30 8C 45 86 45 82 42 80 42 80 45 82 45 86 30 8C EE 93 61 9D 61 A8 C4 B4 56 C2 E2 D0

Then until some point in time.....

[00:10:52.025] SCO => 80 01 30 61 9D EE 93 30 8C 45 86 45 82 42 80 42 80 45 82 45 86 30 8C EE 93 61 9D 61 A8 C4 B4 56 C2 E2 D0 2B E0 F5 EF 00 00 0B 10 D5 1F 1E 2F AA 3D 3C 4B
[00:10:52.041] EVT <= 6E 00
[00:10:52.043] EVT <= 6F 00
[00:10:52.046] SCO => 80 01 30 9F 57 9F Task watchdog got triggered. The following tasks did not feed the watchdog in time:
Tasks currently running:
CPU 0: main
ASSERT_ERR((EM_BT_RXDESC_OFFSET + ld_env.curr_rxdesc_index * REG_EM_BT_RXDESC_SIZE) == bt_et_currentrxdescptr_currentrxdescptr_getf()), in ld_acl.c at line 1900abort() was called at PC 0x40081e0d on core 0
0x40081e0d: lock_acquire_generic at /Users/haoye/esp/esp-idf/components/newlib/./locks.c:141

Backtrace: 0x40087fd0:0x3ffc02c0 0x4008809b:0x3ffc02e0 0x40081e0d:0x3ffc0300 0x40081f2d:0x3ffc0330 0x400d2ada:0x3ffc0350 0x400d2b35:0x3ffc0390 0x400e0c8e:0x3ffc03b0 0x400e0c9f:0x3ffc03d0 0x400ea8d9:0x3ffc0400 0x400e878a:0x3ffc0420 0x4001791d:0x3ffc0440 0x400e8c2e:0x3ffc0460 0x400e8dba:0x3ffc04a0 0x400188f5:0x3ffc04d0 0x40055fca:0x3ffc0510 0x40082f2a:0x3ffc0530 0x40032ae6:0x3ffc0550 0x40034a99:0x3ffc0590 0x4003a85e:0x3ffc05b0 0x400554a1:0x3ffc05d0 0x40084273:0x3ffc05f0 0x4008179d:0x3ffc0610
0x40087fd0: invoke_abort at /Users/haoye/esp/esp-idf/components/esp32/./panic.c:546

0x4008809b: abort at /Users/haoye/esp/esp-idf/components/esp32/./panic.c:546

0x40081e0d: lock_acquire_generic at /Users/haoye/esp/esp-idf/components/newlib/./locks.c:141

0x40081f2d: _lock_acquire_recursive at /Users/haoye/esp/esp-idf/components/newlib/./locks.c:169

0x400d2ada: _puts_r at /Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdio/../../../.././newlib/libc/stdio/puts.c:98 (discriminator 2)

0x400d2b35: puts at /Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdio/../../../.././newlib/libc/stdio/puts.c:138

0x400e0c8e: report_recv_called_from_isr at /Users/haoye/esp/esp-idf/components/btstack/./main.c:96

0x400e0c9f: host_recv_pkt_cb at /Users/haoye/esp/esp-idf/components/btstack/./main.c:120

0x400ea8d9: vhci_send at ??:?

0x400e878a: r_eif_send at ??:?

0x400e8c2e: hci_tx_start at hci_tl.c:?

0x400e8dba: r_hci_tl_send at ??:?

0x40082f2a: r_assert_err at ??:?

0x40084273: r_rwbtdm_isr_wrapper at intc.c:?

0x4008179d: _xt_lowint1 at xtensa_vectors.o:?

[mringwal]

hi. I'll verify the hfp_ag mode later. The hsp looks good. it could be that the crash is caused by logging too much. You could try to skipping logging SCO packets in src/hci_dump.c

Ideally, you should hear a sine wave in the handsfree in hfp_ag and hsp_ag demos.

[mringwal]

well, actually, an assert is triggered:
void report_recv_called_from_isr(void){
printf("host_recv_pkt_cb called from ISR!\n");
}

the callback should not be called from an ISR, but it is. Still, it might be related to the SCO logging, so please try without logging the SCO packets.

[yamiyukiharu]

Hi Matthias! I've tried to comment out all the logging and printing while transmitting SCO packets, I still do not hear a sine wave. Instead, I can hear some very minute noise from time to time, and I get the following results in the log :

Establish audio connection
[00:00:26.591] LOG -- hci.c.1947: Synchronous Connection Complete (status=0) 30:21:98:00:40:CC
[00:00:26.591] LOG -- hci.c.184: create_connection_for_addr 30:21:98:00:40:CC, type fe
[00:00:26.596] LOG -- hsp_ag.c.625: eSCO Connection established.
[00:00:26.601] LOG -- hsp_ag.c.633: sco_handle 0x180, address 30:21:98:00:40:CC, transmission_interval 6 slots, retransmission_interval 4 slots, rx_packet_length 30 bytes, tx_packet_length 30 bytes, air_mode 0x 2 (0x02 == CVSD)
Audio connection established with SCO handle 0x0180.
Task watchdog got triggered. The following tasks did not feed the watchdog in time:
Tasks currently running:
CPU 0: btController
Task watchdog got triggered. The following tasks did not feed the watchdog in time:
Tasks currently running:
CPU 0: main
Task watchdog got triggered. The following tasks did not feed the watchdog in time:
Tasks currently running:
CPU 0: btController
Task watchdog got triggered. The following tasks did not feed the watchdog in time:
Tasks currently running:
CPU 0: main
Task watchdog got triggered. The following tasks did not feed the watchdog in time:
Tasks currently running:
CPU 0: main
Task watchdog got triggered. The following tasks did not feed the watchdog in time:
Tasks currently running:
CPU 0: main
[00:01:00.832] LOG -- hci.c.786: ACL First Fragment but data in buffer for handle 0x80, dropping stale fragments
Task watchdog got triggered. The following tasks did not feed the watchdog in time:
Tasks currently running:
CPU 0: main
Task watchdog got triggered. The following tasks did not feed the watchdog in time:
Tasks currently running:
CPU 0: main
[00:01:10.154] LOG -- hci.c.786: ACL First Fragment but data in buffer for handle 0x80, dropping stale fragments
Task watchdog got triggered. The following tasks did not feed the watchdog in time:
Tasks currently running:
CPU 0: main

Also, the application seem to be stuck somewhere, I could not disconnect or do anything else once I establish the audio connection.

Thanks.

[mringwal]

Thanks for the update. I'll try to reproduce this and file an issue on the esp-idf repository after trying to understand it better.

[mringwal]

Hi. I've tried HFP HF with an iPhone and HFP AG with a Bluetooth loudspeaker. I didn't seem to receive any packets, and only did hear a bit of noise on the speaker.

I've posted on the esp-idf issue list: espressif/esp-idf#1118

Let's see what's the status on this.

[yamiyukiharu]

Thank you so much for the help ! Really appreciate it

[mringwal]

FWIW, HFP works on ESP32 since a while.