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

ESP32: hfp_hf_demo crashed when received or initiated a phone call #107

Closed
nuntipat opened this issue Jan 24, 2018 · 6 comments
Closed

ESP32: hfp_hf_demo crashed when received or initiated a phone call #107

nuntipat opened this issue Jan 24, 2018 · 6 comments

Comments

@nuntipat
Copy link

Dear all,

I've referred to this issue #82 and this issue #1118 on the esp-idf's repository to set up my ESP32 board as a Bluetooth headset connected to my iPhone. I'm using the develop branch with latest esp-idf. I've got the connection working and I can enter 'd' to query network operator and 'i' to initiate phone call. However, right after the phone call is made or the phone rang, the program crashed (core dump) as attached below.

Thank you,
Nuntipat

Error message when receiving a phone call

[00:01:08.027] LOG -- hfp_hf_demo.c.242: USER:'g'
Query operator.
[00:01:08.028] LOG -- hfp.c.127: HFP_TX AT+COPS=3,0

[00:01:08.159] LOG -- hfp_hf.c.971: HFP_RX 
OK
[00:01:08.159] LOG -- hfp.c.127: HFP_TX AT+COPS?

[00:01:08.295] LOG -- hfp_hf.c.971: HFP_RX 
+COPS: 0,0,"AIS"
[00:01:08.295] LOG -- hfp.c.1332: Parsed network operator mode: 0, 
[00:01:08.296] LOG -- hfp.c.1090: format 0, 
[00:01:08.300] LOG -- hfp.c.1126: name AIS

[00:01:08.304] LOG -- hfp_hf.c.971: HFP_RX 
OK
NETWORK_OPERATOR_CHANGED, operator mode: 0, format: 0, name: AIS
[00:01:21.358] LOG -- hfp_hf.c.971: HFP_RX 
+CIEV: 3,1
[00:01:21.358] LOG -- hfp.c.1328: Parsed status of the AG indicator 2, status 
[00:01:21.359] LOG -- hfp.c.1104: 1 

AG_INDICATOR_STATUS_CHANGED, AG indicator 'callsetup' (index: 3) to: 1
[00:01:21.824] LOG -- hfp_hf.c.971: HFP_RX 
+BCS:1
[00:01:21.824] LOG -- hfp.c.1254: hfp parse HFP_CMD_AG_SUGGESTED_CODEC 1

[00:01:21.825] LOG -- hfp_hf.c.506: hfp: codec confirmed: CVSD
[00:01:21.830] LOG -- hfp.c.127: HFP_TX AT+BCS=1

[00:01:21.859] LOG -- hfp_hf.c.971: HFP_RX 
OK
[00:01:21.866] LOG -- hci.c.1888: Connection_incoming: DC:A9:04:49:B8:CA, type 2
[00:01:21.867] LOG -- hci.c.184: create_connection_for_addr DC:A9:04:49:B8:CA, type fe
[00:01:21.870] LOG -- hci.c.3143: sending hci_accept_connection_request, remote eSCO 1
[00:01:21.878] LOG -- hfp_hf.c.589: HFP: sending hci_accept_connection_request, sco_voice_setting 0x60
[00:01:21.905] LOG -- hci.c.1954: Synchronous Connection Complete (status=0) DC:A9:04:49:B8:CA
[00:01:21.905] LOG -- hfp.c.659: eSCO Connection established. 

[00:0ASSERT_ERR(0), in ld_acl.c at line 4245abort() was called at PC 0x40082829 on core 0
0x40082829: lock_acquire_generic at /home/nuntipat/esp/esp-idf/components/newlib/./locks.c:141


Backtrace: 0x4008a3b0:0x3ffc02e0 0x4008a54b:0x3ffc0300 0x40082829:0x3ffc0320 0x40082949:0x3ffc0350 0x400d36de:0x3ffc0370 0x400d3739:0x3ffc03b0 0x400e4b5e:0x3ffc03d0 0x400e4b6f:0x3ffc03f0 0x400f3aec:0x3ffc0420 0x400edc32:0x3ffc0440 0x4001791d:0x3ffc0460 0x400ee1b1:0x3ffc0480 0x400ee3a2:0x3ffc04c0 0x400188f5:0x3ffc04f0 0x40055fca:0x3ffc0530 0x40083aae:0x3ffc0550 0x40031b6a:0x3ffc0570 0x400156a5:0x3ffc05a0 0x400552cd:0x3ffc05c0 0x4008667b:0x3ffc05e0 0x4008201a:0x3ffc0600 0x400e2ef0:0x00000000
0x4008a3b0: invoke_abort at /home/nuntipat/esp/esp-idf/components/esp32/./panic.c:648

0x4008a54b: abort at /home/nuntipat/esp/esp-idf/components/esp32/./panic.c:648

0x40082829: lock_acquire_generic at /home/nuntipat/esp/esp-idf/components/newlib/./locks.c:141

0x40082949: _lock_acquire_recursive at /home/nuntipat/esp/esp-idf/components/newlib/./locks.c:169

0x400d36de: _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)

0x400d3739: 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

0x400e4b5e: report_recv_called_from_isr at /home/nuntipat/esp/esp-idf/components/btstack/./main.c:98

0x400e4b6f: host_recv_pkt_cb at /home/nuntipat/esp/esp-idf/components/btstack/./main.c:122

0x400f3aec: vhci_send at ??:?

0x400edc32: r_eif_send at ??:?

0x400ee1b1: hci_tx_start at hci_tl.c:?

0x400ee3a2: r_hci_tl_send at ??:?

0x40083aae: r_assert_err at ??:?

0x4008667b: r_rwbtdm_isr_wrapper at intc.c:?

0x4008201a: _xt_lowint1 at /home/nuntipat/esp/esp-idf/components/freertos/./xtensa_vectors.S:1105

0x400e2ef0: uart_tx_char at /home/nuntipat/esp/esp-idf/components/vfs/./vfs_uart.c:117

================= CORE DUMP START =================
HOoAAAcAAAB0AQAA
3Nf8PyAC/D/U1/w/
sM/8P3DX/D8IyUIAiC38P4gt/D/c1/w/gC38PxgAAAAU0CfmzAC3AtzX/D8AAAAA
AQAAANjF/D9tYWluAEtphyT15dApB9IAAAAAANTX/D8AAAAAIQUGAAEAAAACAAAA

Error message when initiate a phone call

[00:02:18.093] LOG -- hfp_hf_demo.c.252: USER:'i'
Dial 1234567
[00:02:18.093] LOG -- hfp.c.127: HFP_TX ATD1234567;

[00:02:18.186] LOG -- hfp_hf.c.971: HFP_RX 
OK
[00:02:18.321] LOG -- hfp_hf.c.971: HFP_RX 
+CIEV: 3,2
[00:02:18.321] LOG -- hfp.c.1328: Parsed status of the AG indicator 2, status 
[00:02:18.322] LOG -- hfp.c.1104: 2 

AG_INDICATOR_STATUS_CHANGED, AG indicator 'callsetup' (index: 3) to: 2
[00:02:18.505] LOG -- hfp_hf.c.971: HFP_RX 
+BCS:1
[00:02:18.505] LOG -- hfp.c.1254: hfp parse HFP_CMD_AG_SUGGESTED_CODEC 1

[00:02:18.505] LOG -- hfp_hf.c.506: hfp: codec confirmed: CVSD
[00:02:18.511] LOG -- hfp.c.127: HFP_TX AT+BCS=1

[00:02:18.548] LOG -- hfp_hf.c.971: HFP_RX 
OK
[00:02:18.557] LOG -- hci.c.1888: Connection_incoming: DC:A9:04:49:B8:CA, type 2
[00:02:18.558] LOG -- hci.c.184: create_connection_for_addr DC:A9:04:49:B8:CA, type fe
[00:02:18.561] LOG -- hci.c.3143: sending hci_accept_connection_request, remote eSCO 1
[00:02:18.569] LOG -- hfp_hf.c.589: HFP: sending hci_accept_connection_request, sco_voice_setting 0x60
[00:02:18.596] LOG -- hci.c.1954: Synchronous Connection Complete (status=0) DC:A9:04:49:B8:CA
[00:02:18.596] LOG -- hfp.c.659: eSCO Connection established.ASSERT_ERR(0), in ld_acl.c at line 4245abort() was called at PC 0x40082829 on core 0
0x40082829: lock_acquire_generic at /home/nuntipat/esp/esp-idf/components/newlib/./locks.c:141


Backtrace: 0x4008a3b0:0x3ffc02e0 0x4008a54b:0x3ffc0300 0x40082829:0x3ffc0320 0x40082949:0x3ffc0350 0x400d36de:0x3ffc0370 0x400d3739:0x3ffc03b0 0x400e4b5e:0x3ffc03d0 0x400e4b6f:0x3ffc03f0 0x400f3aec:0x3ffc0420 0x400edc32:0x3ffc0440 0x4001791d:0x3ffc0460 0x400ee1b1:0x3ffc0480 0x400ee3a2:0x3ffc04c0 0x400188f5:0x3ffc04f0 0x40055fca:0x3ffc0530 0x40083aae:0x3ffc0550 0x40031b6a:0x3ffc0570 0x400156a5:0x3ffc05a0 0x400552cd:0x3ffc05c0 0x4008667b:0x3ffc05e0 0x4008201a:0x3ffc0600 0x400e2ee5:0x00000000
0x4008a3b0: invoke_abort at /home/nuntipat/esp/esp-idf/components/esp32/./panic.c:648

0x4008a54b: abort at /home/nuntipat/esp/esp-idf/components/esp32/./panic.c:648

0x40082829: lock_acquire_generic at /home/nuntipat/esp/esp-idf/components/newlib/./locks.c:141

0x40082949: _lock_acquire_recursive at /home/nuntipat/esp/esp-idf/components/newlib/./locks.c:169

0x400d36de: _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)

0x400d3739: 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

0x400e4b5e: report_recv_called_from_isr at /home/nuntipat/esp/esp-idf/components/btstack/./main.c:98

0x400e4b6f: host_recv_pkt_cb at /home/nuntipat/esp/esp-idf/components/btstack/./main.c:122

0x400f3aec: vhci_send at ??:?

0x400edc32: r_eif_send at ??:?

0x400ee1b1: hci_tx_start at hci_tl.c:?

0x400ee3a2: r_hci_tl_send at ??:?

0x40083aae: r_assert_err at ??:?

0x4008667b: r_rwbtdm_isr_wrapper at intc.c:?

0x4008201a: _xt_lowint1 at /home/nuntipat/esp/esp-idf/components/freertos/./xtensa_vectors.S:1105

0x400e2ee5: uart_tx_char at /home/nuntipat/esp/esp-idf/components/vfs/./vfs_uart.c:117


================= CORE DUMP START =================
HOoAAAcAAAB0AQAA
3Nf8PyAC/D/U1/w/
sM/8P3DX/D91pkMAiC38P4gt/D/c1/w/gC38PxgAAAAU0CfmzAC3AtzX/D8AAAAA
AQAAANjF/D9tYWluAEtphyT15dApB9IAAAAAANTX/D8AAAAAIQUGAAEAAAACAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAADyp/D+kqfw/DKr8PwAAAAAAAAAA
@mringwal
Copy link
Member

hi! In both cases, it crashes because BTstack's packet handler is called from interrupt context.
(see report_recv_called_from_isr in the backlog). However, I was told by Espressif that this is somehow the result of an assert in the ESP32 Bluetooth Controller implementation. So, the actual error is:

0x40083aae: r_assert_err at ??:?

Feel free to post your logs as issues at github/esp-idf to make them aware that more people would like to use SCO on he ESP32.

In general, we still don't know how to receive/send SCO packets with the ESP32 - espressif/esp-idf#1118

Without that, even if it wouldn't crash, HFP cannot be used.

@nuntipat
Copy link
Author

Thank you very much for the feedback! Highly appreciated. I will create an issue at github/esp-idf as suggested.

@allex1978
Copy link

hi! In both cases, it crashes because BTstack's packet handler is called from interrupt context.
(see report_recv_called_from_isr in the backlog). However, I was told by Espressif that this is somehow the result of an assert in the ESP32 Bluetooth Controller implementation. So, the actual error is:

0x40083aae: r_assert_err at ??:?

Feel free to post your logs as issues at github/esp-idf to make them aware that more people would like to use SCO on he ESP32.

In general, we still don't know how to receive/send SCO packets with the ESP32 - espressif/esp-idf#1118

Without that, even if it wouldn't crash, HFP cannot be used.

Hi, HFP works(SCO over HCI) fine with esp-idf bluedriod stack... but only with CVSD codec. Sound is not good (8000hz only). I used i2s mems mic for input and external i2s DAC for output(used both i2s buses). I`m want to use mSBC codec and tried the bluekitchen stack... and output buffer transmitted to i2s have only zeros in HFP bluekitchen example.

@mringwal
Copy link
Member

hi. few quetions:

  • how did you try esp-idf bluedroid? didn't see an example yet.
  • was the audio received at the remote side fine as well? sending seems to be the tricker part

For BTstack: please try the current version of develop, with this week update to sco over hci config. I tried this week, see espressif/esp-idf#1118

@allex1978
Copy link

  1. I rebuilded a2dp example to HFP.
  2. Yes. audio received and transmitted at remote side well. but with 8000hz and sometimes clicks(looks like packet losses)

@allex1978
Copy link

hi. few quetions:

  • how did you try esp-idf bluedroid? didn't see an example yet.
  • was the audio received at the remote side fine as well? sending seems to be the tricker part

For BTstack: please try the current version of develop, with this week update to sco over hci config. I tried this week, see espressif/esp-idf#1118

Thanks a lot! with BTstack-develop works. mSBC+PLC+SCO_DEMO_MODE_SINE i hear the remote phone and the remote phone hear a sinus. Perfect! Next step is add i2s mems microphone.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@mringwal @nuntipat @allex1978