search

bluekitchen / btstack

Dual-mode Bluetooth stack, with small memory footprint.
http://bluekitchen-gmbh.com
Other
1.74k stars 618 forks source link

The device reboot when using hfp_hf example on ESP32 with IDF version 4.0 and 4.1 #297

Closed vvhh2002 closed 3 years ago

vvhh2002 commented 4 years ago

Describe the bug The device reboot when using hfp_hs example on ESP32 with IDF version 4.0 and 4.1

To Reproduce Steps to reproduce the behavior:

  1. Run example 'hfp_hf'
  2. Connect to/from remove device IPhone Xs
  3. Start action 'make a call'

Expected behavior

ASSERT_PARAM(1 0), in rwbt.c at line 314
Guru Meditation Error: Core  0 panic'ed (Interrupt wdt timeout on CPU0)

HCI Packet Logs

I (11762) BTS: hfp.c.1636: HFP_HF_RX: '\r\n+BIND:1,1\r\n'
I (11762) BTS: hfp.c.840: command '+BIND', handsfree 1
I (11762) BTS: hfp.c.1279: HFP_CMD_SET_GENERIC_STATUS_INDICATOR_STATUS set indicator at index 1, to 1

I (11772) BTS: hfp.c.1636: HFP_HF_RX: '\r\n+BIND:2,1\r\n'
I (11782) BTS: hfp.c.840: command '+BIND', handsfree 1
I (11792) BTS: hfp.c.1279: HFP_CMD_SET_GENERIC_STATUS_INDICATOR_STATUS set indicator at index 1, to 1

I (11802) BTS: hfp.c.1636: HFP_HF_RX: '\r\nOK\r\n'
I (11802) BTS: hfp.c.840: command 'OK', handsfree 1
Service level connection established XX:XX:XX:XX:XX:XX.

Speaker volume: gain 9
Microphone volume: gain 9
I (11822) BTS: hfp.c.176: HFP_TX AT+VGM=9

I (11872) BTS: hfp.c.1636: HFP_HF_RX: '\r\nOK\r\n'
I (11872) BTS: hfp.c.840: command 'OK', handsfree 1
I (11872) BTS: hfp.c.176: HFP_TX AT+VGS=9

I (11922) BTS: hfp.c.1636: HFP_HF_RX: '\r\nOK\r\n'
I (11922) BTS: hfp.c.840: command 'OK', handsfree 1
I (15232) BTS: test_btstack_hfp_hf.c.384: USER:'?'
Query Subscriber Number
I (15252) BTS: hfp.c.176: HFP_TX AT+CNUM

I (15302) BTS: hfp.c.1636: HFP_HF_RX: '\r\nOK\r\n'
I (15312) BTS: hfp.c.840: command 'OK', handsfree 1
I (19322) BTS: l2cap.c.1966: create channel 0x3ffdfc8c, local_cid 0x0043
I (19322) BTS: hci.c.4630: gap_request_security_level requested level 0, planned level 2, current level 2
I (19332) BTS: hci.c.4497: hci_emit_security_level 2 for handle 81
I (19332) BTS: l2cap.c.2388: l2cap - security level update for handle 0x0081
I (19362) BTS: l2cap.c.2398: channel 0x3ffdfd34, cid 0042 - state 12: actual 2 >= required 2?
I (19372) BTS: l2cap.c.2398: channel 0x3ffdfc8c, cid 0043 - state 5: actual 2 >= required 0?
I (19372) BTS: l2cap.c.1067: L2CAP_EVENT_INCOMING_CONNECTION addr XX:XX:XX:XX:XX:XX handle 0x81 psm 0x1 local_cid 0x43 remote_cid 0xcc0d
I (19392) BTS: l2cap.c.2511: L2CAP_ACCEPT_CONNECTION local_cid 0x43
I (19412) BTS: l2cap.c.1217: l2cap_stop_rtx for local cid 0x43
I (19412) BTS: l2cap.c.1226: l2cap_start_rtx for local cid 0x43
I (19452) BTS: l2cap.c.2720: L2CAP signaling handler code 4, state 11
I (19452) BTS: l2cap.c.2567: Remote MTU 256
I (19462) BTS: l2cap.c.2720: L2CAP signaling handler code 5, state 11
I (19462) BTS: l2cap.c.1217: l2cap_stop_rtx for local cid 0x43
I (19482) BTS: l2cap.c.2651: l2cap_signaling_handle_configure_response
I (19482) BTS: l2cap.c.1033: L2CAP_EVENT_CHANNEL_OPENED status 0x0 addr XX:XX:XX:XX:XX:XX handle 0x81 psm 0x1 local_cid 0x43 remote_cid 0xcc0d local_mtu 1691, remote_mtu 256, flush_timeout 0
I (19742) BTS: l2cap.c.2720: L2CAP signaling handler code 6, state 12
I (19762) BTS: l2cap.c.1061: L2CAP_EVENT_CHANNEL_CLOSED local_cid 0x43
I (19762) BTS: l2cap.c.1972: free channel 0x3ffdfc8c, local_cid 0x0043
I (19782) BTS: l2cap.c.1217: l2cap_stop_rtx for local cid 0x43
I (27532) BTS: test_btstack_hfp_hf.c.139: USER:'a'
Establish Service level connection to device with Bluetooth address XX:XX:XX:XX:XX:XX...
I (27562) BTS: hfp.c.1480: hfp_connect XX:XX:XX:XX:XX:XX, hfp_connection 0x3ffdf8bc
I (38552) BTS: hfp.c.1636: HFP_HF_RX: '\r\n+CIEV: 3,1\r\n'
I (38552) BTS: hfp.c.840: command '+CIEV', handsfree 1
I (38552) BTS: hfp.c.1442: Parsed status of the AG indicator 2, status 
I (38572) BTS: hfp.c.1214: 1 

AG_INDICATOR_STATUS_CHANGED, AG indicator (index: 3) to: 1 of range [0, 3], name 'callsetup'
I (39532) BTS: hfp.c.1636: HFP_HF_RX: '\r\n+BCS:2\r\n'
I (39532) BTS: hfp.c.840: command '+BCS', handsfree 1
I (39532) BTS: hfp.c.1368: hfp parse HFP_CMD_AG_SUGGESTED_CODEC 2

I (39552) BTS: hfp_hf.c.528: hfp: codec confirmed: mSBC
I (39552) BTS: hfp.c.176: HFP_TX AT+BCS=2

I (39622) BTS: hci.c.2191: Connection_incoming: XX:XX:XX:XX:XX:XX, type 2
I (39622) BTS: hci.c.193: create_connection_for_addr XX:XX:XX:XX:XX:XX, type fc
I (39652) BTS: hfp.c.641: hf accept sco 2

I (39652) BTS: hfp_hf.c.625: HFP: sending hci_accept_connection_request, sco_voice_setting 0x43
I (39752) BTS: hci.c.2247: Synchronous Connection Complete (status=0) XX:XX:XX:XX:XX:XX
I (39752) BTS: hfp.c.699: eSCO Connection established. 

I (39762) BTS: hfp.c.707: sco_handle 0x181, address XX:XX:XX:XX:XX:XX, transmission_interval 12 slots, retransmission_interval 2 slots,  rx_packet_length 60 bytes, tx_packet_length 60 bytes, air_mode 0x 3 (0x02 == CVSD)

Audio connection established with SCO handle 0x0181.
Using mSBC codec.
ASSERT_PARAM(1 0), in rwbt.c at line 314
Guru Meditation Error: Core  0 panic'ed (Interrupt wdt timeout on CPU0)
Core 0 register dump:
PC      : 0x40085b7a  PS      : 0x00060034  A0      : 0x8008a580  A1      : 0x3ffbe270  
0x40085b7a: r_assert_param at ??:?

A2      : 0x00000001  A3      : 0x00000000  A4      : 0x00000000  A5      : 0x60008054  
A6      : 0x3ffbdbb4  A7      : 0x60008050  A8      : 0x80085b75  A9      : 0x3ffbe250  
A10     : 0x00000004  A11     : 0x00000000  A12     : 0x6000804c  A13     : 0xffffffff  
A14     : 0x00000000  A15     : 0xfffffffc  SAR     : 0x00000004  EXCCAUSE: 0x00000005  
EXCVADDR: 0x00000000  LBEG    : 0x40085aad  LEND    : 0x40085ab4  LCOUNT  : 0x00000000  
0x40085aad: r_assert_param at ??:?

0x40085ab4: r_assert_param at ??:?

Core 0 was running in ISR context:
EPC1    : 0x40134344  EPC2    : 0x00000000  EPC3    : 0x00000000  EPC4    : 0x40085b7a
0x40134344: _vfprintf_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/vfprintf.c:1685

0x40085b7a: r_assert_param at ??:?

ELF file SHA256: 2cd5c115faab0b5f

Backtrace: 0x40085b77:0x3ffbe270 0x4008a57d:0x3ffbe290 0x4008a997:0x3ffbe2b0 0x40084f9d:0x3ffbe2d0 0x40134341:0x3ffd97f0 0x401351e9:0x3ffd9b00 0x40084849:0x3ffd9b30 0x40084871:0x3ffd9b60 0x400e485e:0x3ffd9bb0 0x400ef7c5:0x3ffd9c00 0x400f134f:0x3ffd9c80 0x400f13e8:0x3ffd9ca0 0x400f37de:0x3ffd9cc0 0x400f4281:0x3ffd9d10 0x4013ef12:0x3ffd9d30 0x400fb2de:0x3ffd9d50 0x400fca9e:0x3ffd9d70 0x400fcacd:0x3ffd9d90 0x400f6d5d:0x3ffd9db0 0x400fa9b1:0x3ffd9dd0 0x400fab4f:0x3ffd9e10 0x400e3e44:0x3ffd9e30 0x400e3e95:0x3ffd9e60 0x400e4461:0x3ffd9e80 0x400f690d:0x3ffd9ec0 0x400da2fb:0x3ffd9ee0 0x400e25c4:0x3ffd9f00 0x400d91e9:0x3ffd9f20 0x4009327d:0x3ffd9f60
0x40085b77: r_assert_param at ??:?

0x4008a57d: r_rwbt_isr at ??:?

0x4008a997: r_rwbtdm_isr_wrapper at intc.c:?

0x40084f9d: _xt_lowint1 at /esp/esp-idf/components/freertos/xtensa_vectors.S:1153

0x40134341: _vfprintf_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/vfprintf.c:1685

0x401351e9: vprintf at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/vprintf.c:34

0x40084849: esp_log_writev at /esp/esp-idf/components/log/log.c:121

0x40084871: esp_log_write at /esp/esp-idf/components/log/log.c:121

0x400e485e: hci_dump_log at custom/esp_hci_dump.c:444

0x400ef7c5: hfp_log_rfcomm_message at btstack/src/classic/hfp.c:375

0x400f134f: hfp_hf_handle_rfcomm_data at btstack/src/classic/hfp_hf.c:1095

0x400f13e8: rfcomm_packet_handler at btstack/src/classic/hfp_hf.c:1123

0x400f37de: rfcomm_channel_packet_handler_uih at btstack/src/classic/rfcomm.c:2560

0x400f4281: rfcomm_packet_handler at btstack/src/classic/rfcomm.c:2560

0x4013ef12: l2cap_dispatch_to_channel at btstack/src/l2cap.c:1346

0x400fb2de: l2cap_acl_classic_handler_for_channel at btstack/src/l2cap.c:1346

0x400fca9e: l2cap_acl_classic_handler at btstack/src/l2cap.c:1346

0x400fcacd: l2cap_acl_handler at btstack/src/l2cap.c:1346

0x400f6d5d: hci_emit_acl_packet at btstack/src/hci.c:4561

0x400fa9b1: acl_handler at btstack/src/hci.c:4561

0x400fab4f: packet_handler at btstack/src/hci.c:4561

0x400e3e44: transport_deliver_packets at btstack_port_esp32.c:180

0x400e3e95: transport_process at btstack_port_esp32.c:196

0x400e4461: btstack_run_loop_freertos_execute at btstack_run_loop_freertos.c:213

0x400f690d: btstack_run_loop_execute at btstack/src/btstack_run_loop.c:189

0x400da2fb: test_btstack_hf_run at test_btstack_hfp_hf.c:674

0x400e25c4: esp_console_run at /esp/esp-idf/components/console/commands.c:200

0x400d91e9: init_debug_console at debug_console.c:197

0x4009327d: vPortTaskWrapper at /esp/esp-idf/components/freertos/port.c:436

Core 1 register dump:
PC      : 0x4013f482  PS      : 0x00060234  A0      : 0x800d689e  A1      : 0x3ffbd260  
0x4013f482: esp_pm_impl_waiti at /esp/esp-idf/components/esp32/pm_esp32.c:486

A2      : 0x00000000  A3      : 0x00000000  A4      : 0x00000001  A5      : 0x80000001  
A6      : 0x00000001  A7      : 0x00000000  A8      : 0x800d61fe  A9      : 0x3ffbd230  
A10     : 0x00000000  A11     : 0x00060623  A12     : 0x00060620  A13     : 0x3ffc2c8c  
A14     : 0x00000015  A15     : 0x3ffbd990  SAR     : 0x00000000  EXCCAUSE: 0x00000005  
EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000  

ELF file SHA256: 2cd5c115faab0b5f

Backtrace: 0x4013f47f:0x3ffbd260 0x400d689b:0x3ffbd280 0x40095531:0x3ffbd2a0 0x4009327d:0x3ffbd2c0
0x4013f47f: esp_pm_impl_waiti at /esp/esp-idf/components/esp32/pm_esp32.c:484

0x400d689b: esp_vApplicationIdleHook at /esp/esp-idf/components/esp_common/src/freertos_hooks.c:86

0x40095531: prvIdleTask at /esp/esp-idf/components/freertos/tasks.c:4691

0x4009327d: vPortTaskWrapper at /esp/esp-idf/components/freertos/port.c:436

Rebooting...
ets Jun  8 2016 00:22:57

Environment: (please complete the following information):

vvhh2002 commented 4 years ago

The following exception occurred in IDF 4.0.1：

I (6369) phy: phy_version: 4180, cb3948e, Sep 12 2019, 16:39:13, 0, 0
[00:00:06.379] LOG -- hci.c.4397: BTSTACK_EVENT_STATE 1
[00:00:06.379] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 60, size 3
[00:00:06.389] LOG -- hci.c.1209: hci_initializing_run: substate 0, can send 1
I (6389) hfp_hf: btstack_main end!
[00:00:06.389] LOG -- btstack_run_loop_freertos.c.219: RL: execute
[00:00:06.399] LOG -- hci.c.1559: Command complete for expected opcode 0c03 at substate 1
[00:00:06.409] LOG -- hfp.c.625: HFP HCI event handler type 4, event type e, size 6
[00:00:06.419] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:06.429] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 4294967295
[00:00:06.429] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:06.439] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 4294967295
[00:00:06.549] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 6e, size 2
[00:00:06.559] LOG -- hci.c.1209: hci_initializing_run: substate 2, can send 1
[00:00:06.579] LOG -- hci.c.2059: Manufacturer: 0x0060
[00:00:06.579] LOG -- hci.c.1559: Command complete for expected opcode 1001 at substate 3
[00:00:06.579] LOG -- hfp.c.625: HFP HCI event handler type 4, event type e, size 14
[00:00:06.599] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:06.619] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 4294967295
[00:00:06.619] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 6e, size 2
[00:00:06.639] LOG -- hci.c.1209: hci_initializing_run: substate 4, can send 1
[00:00:06.639] LOG -- hci.c.1955: local name: 
[00:00:06.639] LOG -- hci.c.1559: Command complete for expected opcode 0c14 at substate 5
[00:00:06.659] LOG -- hci.c.1689: Received local name, need baud change 0
[00:00:06.659] LOG -- hfp.c.625: HFP HCI event handler type 4, event type e, size 254
[00:00:06.679] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:06.699] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 4294967295
[00:00:06.699] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 6e, size 2
[00:00:06.719] LOG -- hci.c.1209: hci_initializing_run: substate 8, can send 1
[00:00:06.719] LOG -- hci.c.2074: Local supported commands summary bf - 03
[00:00:06.729] LOG -- hci.c.1559: Command complete for expected opcode 1002 at substate 15
[00:00:06.739] LOG -- hfp.c.625: HFP HCI event handler type 4, event type e, size 70
[00:00:06.759] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:06.759] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 4294967295
[00:00:06.779] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 6e, size 2
[00:00:06.779] LOG -- hci.c.1209: hci_initializing_run: substate 22, can send 1
[00:00:06.799] LOG -- hci.c.2012: Local Address, Status: 0x00: Addr: A4:CF:12:6D:5F:3A
[00:00:06.799] LOG -- hci.c.1559: Command complete for expected opcode 1009 at substate 23
[00:00:06.819] LOG -- hfp.c.625: HFP HCI event handler type 4, event type e, size 12
[00:00:06.819] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:06.839] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 4294967295
[00:00:06.859] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 6e, size 2
[00:00:06.859] LOG -- hci.c.1209: hci_initializing_run: substate 24, can send 1
[00:00:06.879] LOG -- hci.c.1972: hci_read_buffer_size: ACL size module 1021 -> used 1021, count 9 / SCO size 255, count 4
[00:00:06.879] LOG -- hci.c.1559: Command complete for expected opcode 1005 at substate 25
[00:00:06.899] LOG -- hfp.c.625: HFP HCI event handler type 4, event type e, size 13
[00:00:06.919] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:06.919] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 4294967295
[00:00:06.939] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 6e, size 2
[00:00:06.939] LOG -- hci.c.1209: hci_initializing_run: substate 26, can send 1
[00:00:06.959] LOG -- hci.c.2041: Packet types cc18, eSCO 1
[00:00:06.959] LOG -- hci.c.2044: BR/EDR support 1, LE support 0
[00:00:06.959] LOG -- hci.c.1559: Command complete for expected opcode 1003 at substate 27
[00:00:06.979] LOG -- hfp.c.625: HFP HCI event handler type 4, event type e, size 14
Supported codecs: CVSD, mSBC
[00:00:06.999] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:06.999] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 4294967295
[00:00:07.019] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 6e, size 2
[00:00:07.039] LOG -- hci.c.1209: hci_initializing_run: substate 28, can send 1
[00:00:07.039] LOG -- hci.c.1559: Command complete for expected opcode 0c33 at substate 29
[00:00:07.039] LOG -- hfp.c.625: HFP HCI event handler type 4, event type e, size 6
[00:00:07.059] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:07.059] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 4294967295
[00:00:07.079] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 6e, size 2
[00:00:07.099] LOG -- hci.c.1209: hci_initializing_run: substate 30, can send 1
[00:00:07.099] LOG -- hci.c.1559: Command complete for expected opcode 0c31 at substate 31
[00:00:07.099] LOG -- hfp.c.625: HFP HCI event handler type 4, event type e, size 6
[00:00:07.119] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:07.139] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 4294967295
[00:00:07.139] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 6e, size 2
[00:00:07.159] LOG -- hci.c.1209: hci_initializing_run: substate 32, can send 1
[00:00:07.159] LOG -- hci.c.1559: Command complete for expected opcode 0c01 at substate 33
[00:00:07.179] LOG -- hfp.c.625: HFP HCI event handler type 4, event type e, size 6
[00:00:07.179] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:07.199] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 4294967295
[00:00:07.199] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 6e, size 2
[00:00:07.219] LOG -- hci.c.1209: hci_initializing_run: substate 34, can send 1
[00:00:07.219] LOG -- hci.c.1559: Command complete for expected opcode 0c56 at substate 35
[00:00:07.239] LOG -- hfp.c.625: HFP HCI event handler type 4, event type e, size 6
[00:00:07.239] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:07.259] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 4294967295
[00:00:07.259] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 6e, size 2
[00:00:07.279] LOG -- hci.c.1209: hci_initializing_run: substate 36, can send 1
[00:00:07.299] LOG -- hci.c.1559: Command complete for expected opcode 0c18 at substate 37
[00:00:07.299] LOG -- hfp.c.625: HFP HCI event handler type 4, event type e, size 6
[00:00:07.319] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:07.319] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 4294967295
[00:00:07.339] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 6e, size 2
[00:00:07.339] LOG -- hci.c.1209: hci_initializing_run: substate 38, can send 1
[00:00:07.359] LOG -- hci.c.1559: Command complete for expected opcode 080f at substate 39
[00:00:07.359] LOG -- hfp.c.625: HFP HCI event handler type 4, event type e, size 6
[00:00:07.379] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:07.379] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 4294967295
[00:00:07.399] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 6e, size 2
[00:00:07.419] LOG -- hci.c.1209: hci_initializing_run: substate 40, can send 1
[00:00:07.419] LOG -- hci.c.1559: Command complete for expected opcode 0c24 at substate 41
[00:00:07.419] LOG -- hfp.c.625: HFP HCI event handler type 4, event type e, size 6
[00:00:07.439] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:07.439] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 4294967295
[00:00:07.459] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 6e, size 2
[00:00:07.479] LOG -- hci.c.1209: hci_initializing_run: substate 42, can send 1
[00:00:07.479] LOG -- hci.c.1559: Command complete for expected opcode 0c13 at substate 43
[00:00:07.479] LOG -- hfp.c.625: HFP HCI event handler type 4, event type e, size 6
[00:00:07.499] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:07.519] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 4294967295
[00:00:07.519] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 6e, size 2
[00:00:07.539] LOG -- hci.c.1209: hci_initializing_run: substate 44, can send 1
[00:00:07.539] LOG -- hci.c.1559: Command complete for expected opcode 0c52 at substate 45
[00:00:07.559] LOG -- hfp.c.625: HFP HCI event handler type 4, event type e, size 6
[00:00:07.559] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:07.579] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 4294967295
[00:00:07.579] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 6e, size 2
[00:00:07.599] LOG -- hci.c.1209: hci_initializing_run: substate 46, can send 1
[00:00:07.599] LOG -- hci.c.1559: Command complete for expected opcode 0c45 at substate 47
[00:00:07.619] LOG -- hfp.c.625: HFP HCI event handler type 4, event type e, size 6
[00:00:07.619] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:07.639] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 4294967295
[00:00:07.639] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 6e, size 2
[00:00:07.659] LOG -- hci.c.1209: hci_initializing_run: substate 48, can send 1
[00:00:07.679] LOG -- hci.c.1559: Command complete for expected opcode 0c7a at substate 49
[00:00:07.679] LOG -- hfp.c.625: HFP HCI event handler type 4, event type e, size 6
[00:00:07.699] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:07.699] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 4294967295
[00:00:07.719] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 6e, size 2
[00:00:07.719] LOG -- hci.c.1209: hci_initializing_run: substate 50, can send 1
[00:00:07.739] LOG -- hci.c.4521: BTSTACK_EVENT_DISCOVERABLE_ENABLED 1
[00:00:07.739] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 66, size 3
[00:00:07.749] LOG -- hci.c.1559: Command complete for expected opcode 0c1a at substate 51
[00:00:07.749] LOG -- hfp.c.625: HFP HCI event handler type 4, event type e, size 6
[00:00:07.769] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:07.769] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 4294967295
[00:00:07.789] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 6e, size 2
[00:00:07.809] LOG -- hci.c.1209: hci_initializing_run: substate 52, can send 1
[00:00:07.809] LOG -- hci.c.1559: Command complete for expected opcode 0c2f at substate 53
[00:00:07.809] LOG -- hfp.c.625: HFP HCI event handler type 4, event type e, size 6
[00:00:07.829] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:07.849] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 4294967295
[00:00:07.849] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 6e, size 2
[00:00:07.869] LOG -- hci.c.1209: hci_initializing_run: substate 54, can send 1
[00:00:07.869] LOG -- hci.c.1559: Command complete for expected opcode 0c5b at substate 55
[00:00:07.889] LOG -- hci.c.1547: hci_init_done -> HCI_STATE_WORKING
[00:00:07.889] LOG -- hci.c.4397: BTSTACK_EVENT_STATE 2
[00:00:07.889] LOG -- port_esp32.c.361: transport: configure SCO over HCI, result 0x0000
BTstack up and running at A4:CF:12:6D:5F:3A
[00:00:07.909] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 60, size 3
[00:00:07.929] LOG -- hfp.c.625: HFP HCI event handler type 4, event type e, size 6
[00:00:07.929] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:07.949] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 4294967295
[00:00:07.969] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 6e, size 2
[00:00:07.969] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:07.989] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 4294967295
[00:00:20.399] LOG -- /Users/victor/Documents/CLionProjects/toccobird-esp/src/components/only_test/test_btstack_hfp_hf.c.139: USER:'a'
Establish Service level connection to device with Bluetooth address XX:XX:XX:XX:XX:XX...
[00:00:20.419] LOG -- hfp.c.432: Create HFP context 0x3ffcfd54: role 2, addr XX:XX:XX:XX:XX:XX
[00:00:20.439] LOG -- hfp.c.1480: hfp_connect XX:XX:XX:XX:XX:XX, hfp_connection 0x3ffcfd54
[00:00:20.439] LOG -- l2cap.c.1999: L2CAP_CREATE_CHANNEL addr XX:XX:XX:XX:XX:XX psm 0x1 mtu 1691 -> local mtu 1691
[00:00:20.459] LOG -- l2cap.c.1966: create channel 0x3ffb7b5c, local_cid 0x0041
[00:00:20.479] LOG -- hci.c.4069: Create_connection to XX:XX:XX:XX:XX:XX
[00:00:20.479] LOG -- hci.c.193: create_connection_for_addr XX:XX:XX:XX:XX:XX, type fd
[00:00:20.499] LOG -- hci.c.4081: conn state 0
[00:00:20.499] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:20.499] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 4294967295
[00:00:20.519] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 6e, size 2
[00:00:20.519] LOG -- hci.c.2120: command status (create connection), status 0, connection 0x3ffda758, addr XX:XX:XX:XX:XX:XX, type fd
[00:00:20.539] LOG -- hfp.c.625: HFP HCI event handler type 4, event type f, size 6
[00:00:20.549] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:20.559] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 4294967295
[00:00:21.079] LOG -- hci.c.2215: Connection_complete (status=0) XX:XX:XX:XX:XX:XX
[00:00:21.079] LOG -- hci.c.2235: New connection: handle 129, XX:XX:XX:XX:XX:XX
[00:00:21.089] LOG -- hci.c.4466: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 1
[00:00:21.089] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 61, size 3
[00:00:21.109] LOG -- l2cap.c.1896: connection complete con_handle 0081 - for channel 0x3ffb7b5c cid 0x0041
[00:00:21.109] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 3, size 13
[00:00:21.129] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 1b, size 5
[00:00:21.129] LOG -- hfp.c.625: HFP HCI event handler type 4, event type f, size 6
[00:00:21.139] LOG -- hci.c.2288: HCI_EVENT_READ_REMOTE_SUPPORTED_FEATURES_COMPLETE, bonding flags 6, eSCO 1
[00:00:21.139] LOG -- l2cap.c.2381: remote supported features, channel 0x3ffb7b5c, cid 0041 - state 4
[00:00:21.169] LOG -- l2cap.c.1924: l2cap received remote supported features, sec_level_0_allowed for psm 1 = 1
[00:00:21.169] LOG -- hfp.c.625: HFP HCI event handler type 4, event type b, size 13
[00:00:21.189] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:21.209] LOG -- btstack_run_loop_freertos.c.252: RL: now 21209, expires 31080 -> delta 9871
[00:00:21.209] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 9871
[00:00:21.229] LOG -- hci.c.469: ACL classic buffers: 0 used of 9
[00:00:21.229] LOG -- hci.c.469: ACL classic buffers: 0 used of 9
[00:00:21.229] LOG -- hci.c.469: ACL classic buffers: 0 used of 9
[00:00:21.239] LOG -- hci.c.661: hci_send_acl_packet_fragments entered
[00:00:21.239] LOG -- hci.c.667: hci_send_acl_packet_fragments loop entered
[00:00:21.259] LOG -- hci.c.692: hci_send_acl_packet_fragments loop before send (more fragments 0)
[00:00:21.269] LOG -- hci.c.711: hci_send_acl_packet_fragments loop after send (more fragments 0)
[00:00:21.269] LOG -- hci.c.720: hci_send_acl_packet_fragments loop over
[00:00:21.289] LOG -- l2cap.c.1217: l2cap_stop_rtx for local cid 0x41
[00:00:21.289] LOG -- l2cap.c.1226: l2cap_start_rtx for local cid 0x41
[00:00:21.299] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 6e, size 2
[00:00:21.299] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 13, size 7
[00:00:21.319] LOG -- l2cap.c.2720: L2CAP signaling handler code 3, state 10
[00:00:21.319] LOG -- l2cap.c.1217: l2cap_stop_rtx for local cid 0x41
[00:00:21.329] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:21.329] LOG -- btstack_run_loop_freertos.c.252: RL: now 21329, expires 31080 -> delta 9751
[00:00:21.359] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 9751
[00:00:21.359] LOG -- hci.c.469: ACL classic buffers: 0 used of 9
[00:00:21.379] LOG -- hci.c.469: ACL classic buffers: 0 used of 9
[00:00:21.379] LOG -- hci.c.469: ACL classic buffers: 0 used of 9
[00:00:21.389] LOG -- hci.c.661: hci_send_acl_packet_fragments entered
[00:00:21.389] LOG -- hci.c.667: hci_send_acl_packet_fragments loop entered
[00:00:21.399] LOG -- hci.c.692: hci_send_acl_packet_fragments loop before send (more fragments 0)
[00:00:21.409] LOG -- hci.c.711: hci_send_acl_packet_fragments loop after send (more fragments 0)
[00:00:21.429] LOG -- hci.c.720: hci_send_acl_packet_fragments loop over
[00:00:21.429] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 6e, size 2
[00:00:21.439] LOG -- l2cap.c.2720: L2CAP signaling handler code 4, state 11
[00:00:21.439] LOG -- l2cap.c.2567: Remote MTU 256
[00:00:21.449] LOG -- hfp.c.625: HFP HCI event handler type 4, event type 13, size 7
[00:00:21.459] LOG -- btstack_run_loop_freertos.c.247: RL: portMAX_DELAY 4294967295
[00:00:21.469] LOG -- btstack_run_loop_freertos.c.252: RL: now 21469, expires 31080 -> delta 9611
[00:00:21.489] LOG -- btstack_run_loop_freertos.c.267: RL: wait with timeout 9611
[00:00:21.499] LOG -- hci.c.469: ACL classic buffers: 0 used of 9
[00:00:21.499] LOG -- hci.c.469: ACL classic buffers: 0 used of 9
[00:00:21.509] LOG -- hci.c.469: ACL classic buffers: 0 used of 9
[00:00:21.509] LOG -- hci.c.661: hci_send_acl_packet_fragments entered
[00:00:21.519] LOG -- hci.c.667: hci_send_acl_packet_fragments loop entered
[00:00:21.519] LOG -- hci.c.692: hci_send_acl_packet_fragments loop before send (more fragments 0)
[00:00:21.539] LOG -- hci.c.711: hci_send_acl_packet_fragments loop after send (more fragments 0)
[00:00:21.539] LOG -Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.
Core 0 register dump:
PC      : 0x40014031  PS      : 0x00060531  A0      : 0x80030628  A1      : 0x3ffbe1e0  
A2      : 0x000aaf05  A3      : 0x3ffb238a  A4      : 0x00001fbd  A5      : 0x3ffbcb30  
A6      : 0x00000000  A7      : 0x000046a5  A8      : 0x3ffb4770  A9      : 0x3ffbe1c0  
A10     : 0x00000103  A11     : 0x00000000  A12     : 0x3ffbf984  A13     : 0x3ffbdc04  
A14     : 0x00000008  A15     : 0x00000000  SAR     : 0x00000012  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x000aaf05  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000  
Core 0 was running in ISR context:
EPC1    : 0x40014031  EPC2    : 0x00000000  EPC3    : 0x00000000  EPC4    : 0x00000000

ELF file SHA256: 81118fc8c11c8c5d

Backtrace: 0x4001402e:0x3ffbe1e0 0x40030625:0x3ffbe200 0x400345a5:0x3ffbe240 0x4008743e:0x3ffbe260 0x4008a12a:0x3ffbe290 0x4008a997:0x3ffbe2b0 0x40084f9d:0x3ffbe2d0 0x4013f63f:0x3ffbcaf0 0x400d68b7:0x3ffbcb10 0x40095531:0x3ffbcb30 0x4009327d:0x3ffbcb50
0x4008743e: r_ld_fm_frame_isr at ??:?

0x4008a12a: r_rwbt_isr at ??:?

0x4008a997: r_rwbtdm_isr_wrapper at intc.c:?

0x40084f9d: _xt_lowint1 at /Users/victor/esp/esp-idf/components/freertos/xtensa_vectors.S:1153

0x4013f63f: esp_pm_impl_waiti at /Users/victor/esp/esp-idf/components/esp32/pm_esp32.c:484

0x400d68b7: esp_vApplicationIdleHook at /Users/victor/esp/esp-idf/components/esp_common/src/freertos_hooks.c:86

0x40095531: prvIdleTask at /Users/victor/esp/esp-idf/components/freertos/tasks.c:4691

0x4009327d: vPortTaskWrapper at /Users/victor/esp/esp-idf/components/freertos/port.c:436
vvhh2002 commented 3 years ago

it‘s work on 1.2

mringwal commented 3 years ago

hi! thanks for the update. Do you refer to BTstack v1.2.1 on master? I don't think any changes from us are relevenat for this. Did you update to a newer version of esp-idf? Do you receive a clean sine tone on your headset or are there still glitches in audio?