Errors when closing audio in HFP examples (IDFGH-6239) #7911
Description
Environment
- Development Kit: ESP32-LyraT v4.3
- Module or chip used: ESP32-WROVER-E
- IDF version: v4.3.1-245-gba15ac8634
- Build System: idf.py
- Compiler version: xtensa-esp32-elf-gcc --version
- Operating System: Windows
- (Windows only) environment type: ESP Command Prompt
- Using an IDE?: Yes, ESP-IDF Eclipse
- Power Supply: USB
Problem Description
I have two LyraT boards and I would like to use one as AG and the other one as client. My code is based on hfp_ag and hfp_hf examples respectively, I have only made some changes in order to use I2S to trasmit/receive audio generated from the microphones. Connection and audio opening work good, but I have problems when I try to disconnect audio with the disa console command: most of the times it works ok, but sometimes, randomly, I have different errors as you can see from the Debug Logs section. The cona/disa commands can come from the AG or the client.
As you can see some errors reboot the boards, others flood the serial port with warnings and errors. When these errors happen, I have to reboot the boards in order to use them again. I have modified the following parameters in the menuconfig:
BR/EDR Sync(SCO/eSCO) max connections --> 1BR/EDR Sync(SCO/eSCO) default data path --> HCIaudio(SCO) data path --> HCIWide band speech --> ON
Following other posts I have also tried to modify the #define BTM_SCO_DATA_SIZE_MAX to 240 instead of 120 in the bt_target.h file located at esp-idf\components\bt\host\bluedroid\common\include\common. The system seems more stable with less frequent errors but I don't know if I am supposed to modify that parameter.
Expected Behavior
Close the audio communication with disa command correctly
Actual Behavior
Sometimes the system can't close the audio connection correctly with disa, different errors appear in the serial console.
Code to reproduce this issue
This is the part which is called when the audio closes, it is the same for the AG and the client. I took it from the AG example code.
void bt_app_send_data_shut_down(void)
{
if (s_bt_app_send_data_task_handler) {
vTaskDelete(s_bt_app_send_data_task_handler);
s_bt_app_send_data_task_handler = NULL;
}
if (s_send_data_Semaphore) {
vSemaphoreDelete(s_send_data_Semaphore);
s_send_data_Semaphore = NULL;
}
if(s_periodic_timer) {
ESP_ERROR_CHECK(esp_timer_stop(s_periodic_timer));
ESP_ERROR_CHECK(esp_timer_delete(s_periodic_timer));
}
if (s_m_rb) {
vRingbufferDelete(s_m_rb);
}
return;
}The main task is the following (it is the same for the AG and the client), with semaphore given every 7.5 ms in order to follow the mSBC rules (240 bytes every 7.5 ms); it transfer 240 byte to the ring buffer which is then emptied in the outgoing callback. The structure is similar to hfp_ag example code.
static void bt_app_send_data_task(void * arg) {
uint64_t frame_data_num;
uint32_t item_size = 0;
uint8_t * buf = NULL;
size_t transBytes;
uint8_t * buf2 = NULL;
for (;;) {
if (xSemaphoreTake(s_send_data_Semaphore, (portTickType) portMAX_DELAY)) {
frame_data_num = 480; //byte
buf = osi_malloc(frame_data_num);
i2s_read(I2S_NUM_0, (char * ) buf, frame_data_num, & transBytes, (portTickType) portMAX_DELAY);
// take one channel of the I2S
buf2 = osi_malloc(frame_data_num / 2);
uint32_t j = 0;
for (uint32_t i = 0; i * 2 + 1 < frame_data_num / 2; i++) {
buf2[i * 2] = buf[j];
buf2[i * 2 + 1] = buf[j + 1];
j = j + 4;
}
BaseType_t done = xRingbufferSend(s_m_rb, buf2, frame_data_num / 2, 0);
if (!done) {
ESP_LOGE(BT_HF_TAG, "rb send fail\n");
}
osi_free(buf);
osi_free(buf2);
vRingbufferGetInfo(s_m_rb, NULL, NULL, NULL, NULL, & item_size);
if (item_size >= WBS_PCM_INPUT_DATA_SIZE) { //240 byte
esp_hf_client_outgoing_data_ready();
}
}
}
}Debug Logs
Error 1: cona command from the client, disa command from the AG. As you can see the system works correctly various times before printing the errors.
hfp_hf> cona
connect audio
I (629036) BT_HF: APP HFP event: AUDIO_STATE_EVT
I (629046) BT_HF: --audio state connecting
hfp_hf> E (629076) BT_BTM: btm_sco_connected, handle 180
I (629086) BT_HF: APP HFP event: AUDIO_STATE_EVT
I (629086) BT_HF: --audio state connected_msbc
-----------------------------------------------------------------------------------> disa command sent from the AG
I (635746) BT_HF: APP HFP event: AUDIO_STATE_EVT
I (635746) BT_HF: --audio state disconnected
-----------------------------------------------------------------------------------> cona command sent from the AG
E (638916) BT_BTM: btm_sco_connected, handle 180
I (638926) BT_HF: APP HFP event: AUDIO_STATE_EVT
I (638926) BT_HF: --audio state connected_msbc
-----------------------------------------------------------------------------------> disa command sent from the AG
I (640476) BT_HF: APP HFP event: AUDIO_STATE_EVT
I (640476) BT_HF: --audio state disconnected
-----------------------------------------------------------------------------------> cona command sent from the AG
E (642936) BT_BTM: btm_sco_connected, handle 180
I (642936) BT_HF: APP HFP event: AUDIO_STATE_EVT
I (642936) BT_HF: --audio state connected_msbc
-----------------------------------------------------------------------------------> disa command sent from the AG
I (644536) BT_HF: APP HFP event: AUDIO_STATE_EVT
I (644536) BT_HF: --audio state disconnected
-----------------------------------------------------------------------------------> cona command sent from the AG
E (646976) BT_BTM: btm_sco_connected, handle 180
I (646976) BT_HF: APP HFP event: AUDIO_STATE_EVT
I (646976) BT_HF: --audio state connected_msbc
-----------------------------------------------------------------------------------> disa command sent from the AG
I (649416) BT_HF: APP HFP event: AUDIO_STATE_EVT
I (649416) BT_HF: --audio state disconnected
-----------------------------------------------------------------------------------> cona command sent from the AG
E (662536) BT_BTM: btm_sco_connected, handle 180
I (662536) BT_HF: APP HFP event: AUDIO_STATE_EVT
I (662536) BT_HF: --audio state connected_msbc
-----------------------------------------------------------------------------------> disa command sent from the AG
W (668786) BT_BTM: SCO xmit Q overflow, pkt dropped
W (668786) BT_BTM: stat 10
W (668786) BT_BTM: SCO xmit Q overflow, pkt dropped
W (668796) BT_BTM: stat 10
W (668796) BT_BTM: SCO xmit Q overflow, pkt dropped
W (668796) BT_BTM: stat 10
W (668806) BT_BTM: SCO xmit Q overflow, pkt dropped
W (668806) BT_BTM: stat 10
W (668816) BT_BTM: SCO xmit Q overflow, pkt dropped
W (668816) BT_BTM: stat 10
W (668816) BT_BTM: SCO xmit Q overflow, pkt dropped
W (668836) BT_BTM: stat 10
W (668836) BT_BTM: SCO xmit Q overflow, pkt dropped
W (668836) BT_BTM: stat 10
W (668846) BT_BTM: SCO xmit Q overflow, pkt dropped
W (668846) BT_BTM: stat 10
W (668846) BT_BTM: SCO xmit Q overflow, pkt dropped
W (668856) BT_BTM: stat 10
W (668856) BT_BTM: SCO xmit Q overflow, pkt dropped
W (668866) BT_BTM: stat 10
W (668866) BT_BTM: SCO xmit Q overflow, pkt dropped
W (668866) BT_BTM: stat 10
W (668876) BT_BTM: SCO xmit Q overflow, pkt dropped
W (668876) BT_BTM: stat 10
W (668886) BT_BTM: SCO xmit Q overflow, pkt dropped
W (668896) BT_BTM: stat 10
W (668896) BT_BTM: SCO xmit Q overflow, pkt dropped
W (668896) BT_BTM: stat 10
W (668906) BT_BTM: SCO xmit Q overflow, pkt dropped
W (668906) BT_BTM: stat 10
W (668906) BT_BTM: SCO xmit Q overflow, pkt dropped
W (668916) BT_BTM: stat 10
W (668916) BT_BTM: SCO xmit Q overflow, pkt dropped
W (668926) BT_BTM: stat 10
W (668926) BT_BTM: SCO xmit Q overflow, pkt dropped
W (668926) BT_BTM: stat 10
W (668936) BT_BTM: SCO xmit Q overflow, pkt dropped
W (668946) BT_BTM: stat 10
W (668946) BT_BTM: SCO xmit Q overflow, pkt dropped
W (668956) BT_BTM: stat 10
W (668956) BT_BTM: SCO xmit Q overflow, pkt dropped
W (668966) BT_BTM: stat 10
W (668966) BT_BTM: SCO xmit Q overflow, pkt dropped
W (668966) BT_BTM: stat 10
W (668976) BT_BTM: SCO xmit Q overflow, pkt dropped
W (668976) BT_BTM: stat 10
W (668976) BT_BTM: SCO xmit Q overflow, pkt dropped
W (668986) BT_BTM: stat 10
W (668986) BT_BTM: SCO xmit Q overflow, pkt dropped
W (668996) BT_BTM: stat 10
W (669006) BT_BTM: SCO xmit Q overflow, pkt dropped
W (669006) BT_BTM: stat 10
W (669016) BT_BTM: SCO xmit Q overflow, pkt dropped
W (669016) BT_BTM: stat 10
W (669016) BT_BTM: SCO xmit Q overflow, pkt dropped
W (669026) BT_BTM: stat 10
W (669026) BT_BTM: SCO xmit Q overflow, pkt dropped
W (669026) BT_BTM: stat 10
W (669036) BT_BTM: SCO xmit Q overflow, pkt dropped
W (669036) BT_BTM: stat 10
W (669036) BT_BTM: SCO xmit Q overflow, pkt dropped
W (669046) BT_BTM: stat 10
W (669056) BT_BTM: SCO xmit Q overflow, pkt dropped
W (669066) BT_BTM: stat 10
W (669066) BT_BTM: SCO xmit Q overflow, pkt dropped
W (669066) BT_BTM: stat 10
W (669076) BT_BTM: SCO xmit Q overflow, pkt dropped
W (669076) BT_BTM: stat 10
E (669076) BT_APPL: bta_hf_client_sco_co_out_data invaild air mode: 255
E (669086) BT_APPL: bta_hf_client_sco_co_out_data invaild air mode: 255
E (669086) BT_APPL: bta_hf_client_sco_co_out_data invaild air mode: 255
E (669096) BT_APPL: bta_hf_client_sco_co_out_data invaild air mode: 255
E (669106) BT_APPL: bta_hf_client_sco_co_out_data invaild air mode: 255
E (669116) BT_APPL: bta_hf_client_sco_co_out_data invaild air mode: 255
E (669126) BT_APPL: bta_hf_client_sco_co_out_data invaild air mode: 255
E (669136) BT_APPL: bta_hf_client_sco_co_out_data invaild air mode: 255
E (669136) BT_APPL: bta_hf_client_sco_co_out_data invaild air mode: 255
E (669146) BT_APPL: bta_hf_client_sco_co_out_data invaild air mode: 255
E (669146) BT_APPL: bta_hf_client_sco_co_out_data invaild air mode: 255
E (669146) BT_HF: rb send fail
E (669156) BT_HF: rb send fail
E (669166) BT_HF: rb send fail
E (669156) BT_APPL: bta_hf_client_sco_co_out_data invaild air mode: 255
E (669176) BT_HF: rb send fail
Error 2: audio opening and closing from the client, assert failed.
hfp_hf> cona
connect audio
I (241256) BT_HF: APP HFP event: AUDIO_STATE_EVT
I (241266) BT_HF: --audio state connecting
hfp_hf> E (241286) BT_BTM: btm_sco_connected, handle 180
I (241286) BT_HF: APP HFP event: AUDIO_STATE_EVT
I (241286) BT_HF: --audio state connected_msbc
disa
disconnect audio
hfp_hf> I (242896) BT_HF: APP HFP event: AUDIO_STATE_EVT
I (242896) BT_HF: --audio state disconnected
assert failed: spinlock_acquire spinlock.h:123 ((result == SPINLOCK_FREE) == (lo ck->count == 0))
Backtrace:0x40081743:0x3ffbb3a0 0x40091a4d:0x3ffbb3c0 0x40097525:0x3ffbb3e0 0x40 0950c1:0x3ffbb500 0x400924a8:0x3ffbb520 0x400db351:0x3ffbb560 0x400d9e51:0x3ffbb 580 0x400d9e7a:0x3ffbb5b0 0x40094f1d:0x3ffbb5d0
ELF file SHA256: ff1daf32d46ed3d3
Rebooting...
Error 3: cona and disa from the AG:
hfp_ag> cona
Connect Audio
I (86670) BT_APP_HF: APP HFP event: AUDIO_STATE_EVT
hfp_ag> I (86670) BT_APP_HF: --Audio State connecting
E (86920) BT_BTM: btm_sco_connected, handle 180
I (86920) BT_APP_HF: APP HFP event: AUDIO_STATE_EVT
I (86920) BT_APP_HF: --Audio State connected_msbc
hfp_ag> disa
Disconnect Audio
hfp_ag> ASSERT_ERR(diff_sched_prog >= 0), in ld_acl.c at line 3576
Guru Meditation Error: Core 0 panic'ed (IllegalInstruction). Exception was unhandled.
Memory dump at 0x40083450: 0000f01d 00004136 f01d0000
Core 0 register dump:
PC : 0x40083457 PS : 0x00060831 A0 : 0x800835ad A1 : 0x3ffbe7c0
A2 : 0x3ff9cf33 A3 : 0x00000000 A4 : 0x00000000 A5 : 0x3ff9cd42
A6 : 0x00000df8 A7 : 0xfffffffb A8 : 0x8000814b A9 : 0x3ffbe730
A10 : 0x00000000 A11 : 0x3ffbe754 A12 : 0x3ffbe6ff A13 : 0x00000036
A14 : 0x00000000 A15 : 0x3ffbe705 SAR : 0x00000004 EXCCAUSE: 0x00000000
EXCVADDR: 0x00000000 LBEG : 0x40083521 LEND : 0x40083529 LCOUNT : 0x00000000
Backtrace:0x40083454:0x3ffbe7c0 0x400835aa:0x3ffbe7e0 0x40031471:0x3ffbe800 0x40083e42:0x3ffbe830 0x4008950a:0x3ffbe850 0x4008a047:0x3ffbe870 0x40082d9d:0x3ffbe890 0x4014beff:0x3ffbd690 0x400d9b43:0x3ffbd6b0 0x40093179:0x3ffbd6d0 0x40094f1d:0x3ffbd6f0
ELF file SHA256: 07721cd2ca3624e1
Rebooting...
As I said before, the errors happen randomly, I couldn't find any correlation.