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.

Sign up for GitHub

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

Jump to bottom

Errors when closing audio in HFP examples (IDFGH-6239) #7911

Closed
skateskate opened this issue Nov 15, 2021 · 5 comments
Closed

Errors when closing audio in HFP examples (IDFGH-6239) #7911

skateskate opened this issue Nov 15, 2021 · 5 comments
Labels
Resolution: Done Issue is done internally Status: Done Issue is done internally

Comments

@skateskate
Copy link

skateskate commented Nov 15, 2021 •
edited
Loading

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 --> 1
  • BR/EDR Sync(SCO/eSCO) default data path --> HCI
  • audio(SCO) data path --> HCI
  • Wide 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.
@espressif-bot espressif-bot added the Status: Opened Issue is new label Nov 15, 2021
@github-actions github-actions bot changed the title Errors when closing audio in HFP examples Errors when closing audio in HFP examples (IDFGH-6239) Nov 15, 2021
@BetterJincheng
Copy link
Collaborator

Hi @skateskate,

Please attach the elf file, it does help to locate the crash.

Thanks

@BetterJincheng
Copy link
Collaborator

@skateskate The error-1 is caused by logs. Set #define PCM_GENERATOR_TICK_US (4000) to larger number (7500, 8000 , ...) can be helpful.

The other two errors need the information of elf file.

@skateskate
Copy link
Author

skateskate commented Nov 17, 2021 •
edited
Loading

Hello @BetterJincheng, thanks for the reply.
I have already set the PCM_GENERATOR_TICK_US to 7500, as I have written here:

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 byte every 7.5 ms);

I have initialized I2S to 16 kHz - 16 bit, so every 7.5 ms I can read 480 byte (16 kHz * 7.5 ms * 2 byte * 2 channels) inside bt_app_send_data_task(). Taking only the first channel data (mono audio) I have 240 byte every 7.5 ms as required by mSBC codec and these byte are transferred to the s_m_rb ring buffer.

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.

Is it correct to set BTM_SCO_DATA_SIZE_MAX to 240 or is it better to leave it to 120?

I edited the logs of the Error 1 in the original post to make the operations a little bit clearer, I added where the AG commands are sent. As you can see in the last disa the client doesn't seem to receive the last disconnection event, which then generates the following errors .

Please attach the elf file, it does help to locate the crash.

I have made different tests these days and I don't have anymore the original ELF files, I will save and upload them the next time I have the crashes.

@mingchau
Copy link

Hi @skateskate , May I know if you have fixed the issue? I'm using the LyraT V4.3 as a hands-free unit, it has a lot of problems. Would you mind sharing more about your project.?

@skateskate
Copy link
Author

Hello @mingchau, sorry for the late reply. Unfortunately, I haven't fixed my problems yet, the project is "on hold" for now, I didn't make any progress. The error that was most frequent was the SCO xmit Q overflow, pkt dropped, if you find any way to fix it please let me know.

@espressif-bot espressif-bot added Resolution: NA Issue resolution is unavailable Status: Done Issue is done internally Resolution: Done Issue is done internally and removed Status: Opened Issue is new Resolution: NA Issue resolution is unavailable labels Mar 3, 2022
espressif-bot pushed a commit that referenced this issue Mar 16, 2022
@BetterJincheng
correct the rate of data-producing
1dca246 
Closes #7911
espressif-bot pushed a commit that referenced this issue Apr 20, 2022
@BetterJincheng
correct the rate of data-producing
500e4bd 
Closes #7911
@skateskate skateskate mentioned this issue Jul 12, 2022
Open
@skateskate skateskate mentioned this issue Feb 24, 2023
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Resolution: Done Issue is done internally Status: Done Issue is done internally
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@mingchau @skateskate @espressif-bot @BetterJincheng