zephyrproject-rtos / zephyr

Primary Git Repository for the Zephyr Project. Zephyr is a new generation, scalable, optimized, secure RTOS for multiple hardware architectures.
https://docs.zephyrproject.org
Apache License 2.0
10.45k stars 6.4k forks source link

Losing Bluetooth connection immediately after L2CAP establishment - Bluetooth A2DP (Atom Echo - ESP32-Pico-D4) #75429

Open xG3nesis opened 2 months ago

xG3nesis commented 2 months ago

Hello everyone!

I'm working on implementing an A2DP Source using the A2DP source sample for my M5Stack Atom Echo, which is based on the ESP32-Pico-D4 architecture.

Everything seems to function correctly up to the AVDTP/A2DP establishment process. However, after my ESP32 connects to the L2CAP layer and opens channels, it immediately loses the connection, displaying the error message 0x13. I understand this indicates "Remote User Terminated Connection," but I'm encountering the same error message on my Kali VM (target on which i'm attempting to connect).

The goal, after establishing the AVDTP connection, is to discover the available "Stream Endpoints." Unfortunately, I'm currently unable to achieve this.

Logs and console output Below, you'll find my code and console output from my ESP32:

uart:~$ ␛[8D␛[J[01:04:08.287,000] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x3ffd4318
uart:~$ ␛[8D␛[J[01:04:08.287,000] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x3ffd4318 opcode 0x0405 len 16
uart:~$ ␛[8D␛[J[01:04:08.287,000] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
uart:~$ ␛[8D␛[J[01:04:08.287,000] <dbg> bt_hci_core: tx_processor: TX process start
uart:~$ ␛[8D␛[J[01:04:08.287,000] <dbg> bt_hci_core: hci_core_send_cmd: fetch cmd
uart:~$ ␛[8D␛[J[01:04:08.287,000] <dbg> bt_hci_core: hci_core_send_cmd: Sending command 0x0405 (buf 0x3ffd4318) to driver
uart:~$ ␛[8D␛[J[01:04:08.287,000] <dbg> bt_hci_core: bt_send: buf 0x3ffd4318 len 16 type 0
uart:~$ ␛[8D␛[J[01:04:08.287,000] <dbg> bt_hci_driver_esp32: bt_esp32_send: buf 0x3ffd4318 type 0 len 16
uart:~$ ␛[8D␛[J[01:04:08.287,000] <dbg> bt_hci_driver_esp32: bt_esp32_send: Final HCI buffer:
                                              01 05 04 0d 03 a9 9a 4c  e0 00 18 cc 02 00 00 00 |.......L ........
                                              01                                               |.
uart:~$ ␛[8D␛[J[01:04:08.287,000] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
uart:~$ ␛[8D␛[J[01:04:08.288,000] <dbg> bt_hci_driver_esp32: hci_esp_host_rcv_pkt: host packet data:
                                              04 0f 04 00 05 05 04                             |.......
uart:~$ ␛[8D␛[J[01:04:08.288,000] <dbg> bt_hci_driver_esp32: bt_esp_evt_recv: len 4
uart:~$ ␛[8D␛[J[01:04:08.288,000] <dbg> bt_hci_driver_esp32: hci_esp_host_rcv_pkt: Calling bt_recv(0x3ffd3c5c)
uart:~$ ␛[8D␛[J[01:04:08.288,000] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x3ffd3c5c len 6
uart:~$ ␛[8D␛[J[01:04:08.288,000] <dbg> bt_hci_core: hci_cmd_status: opcode 0x0405
uart:~$ ␛[8D␛[J[01:04:08.288,000] <dbg> bt_hci_core: hci_cmd_done: opcode 0x0405 status 0x00 buf 0x3ffd3c5c
uart:~$ ␛[8D␛[J[01:04:08.288,000] <dbg> bt_hci_core: hci_cmd_done: sync cmd released
uart:~$ ␛[8D␛[J[01:04:08.288,000] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
uart:~$ ␛[8D␛[J[01:04:08.288,000] <dbg> bt_hci_core: tx_processor: TX process start
uart:~$ ␛[8D␛[J[01:04:08.288,000] <dbg> bt_conn: bt_conn_tx_processor: start
uart:~$ ␛[8D␛[J[01:04:08.288,000] <dbg> bt_conn: bt_conn_tx_processor: no connection wants to do stuff
uart:~$ ␛[8D␛[J[01:04:08.288,000] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x3ffd4318 opcode 0x0405 len 0
uart:~$ ␛[8D␛[J[01:04:08.288,000] <dbg> bt_conn: bt_conn_set_state: disconnected -> initiating
uart:~$ ␛[8D␛[J[01:04:08.288,000] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
uart:~$ ␛[8D␛[J[01:04:08.288,000] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1
uart:~$ ␛[8D␛[JConnection pending
uart:~$ ␛[8D␛[Juart:~$ ␛[8D␛[Juart:~$ ␛[8D␛[J[01:04:11.767,000] <dbg> bt_hci_driver_esp32: hci_esp_host_rcv_pkt: host packet data:
                                              04 12 08 00 03 a9 9a 4c  e0 00 01                |.......L ...     
uart:~$ ␛[8D␛[J[01:04:11.767,000] <dbg> bt_hci_driver_esp32: bt_esp_evt_recv: len 8
uart:~$ ␛[8D␛[J--- 107 messages dropped ---
[01:04:11.767,000] <dbg> bt_hci_driver_esp32: hci_esp_host_rcv_pkt: Calling bt_recv(0x3ffd3c5c)
uart:~$ ␛[8D␛[J--- 39 messages dropped ---
[01:04:11.767,000] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x3ffd3c5c len 10
uart:~$ ␛[8D␛[J[01:04:11.767,000] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
uart:~$ ␛[8D␛[J[01:04:11.767,000] <dbg> bt_hci_core: rx_work_handler: buf 0x3ffd3c5c type 1 len 10
uart:~$ ␛[8D␛[J--- 119 messages dropped ---
[01:04:11.767,000] <dbg> bt_hci_core: hci_event: event 0x12
uart:~$ ␛[8D␛[J--- 103 messages dropped ---
[01:04:11.768,000] <dbg> bt_br: bt_hci_role_change: status 0x00 role 1 addr XX:XX:XX:XX:XX:XX
uart:~$ ␛[8D␛[J[01:04:11.768,000] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
uart:~$ ␛[8D␛[J[01:04:11.768,000] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1
uart:~$ ␛[8D␛[J--- 85 messages dropped ---
[01:04:11.789,000] <dbg> bt_l2cap_br: l2cap_br_data_pull: last frag, removing 0x3ffd53a4
uart:~$ ␛[8D␛[J[01:04:11.789,000] <dbg> bt_l2cap_br: l2cap_br_data_pull: chan 0x3ffcc5a0 done
uart:~$ ␛[8D␛[J[01:04:11.789,000] <dbg> bt_conn: bt_conn_tx_processor: pop: cb 0 userdata 0
uart:~$ ␛[8D␛[J--- 142 messages dropped ---
[01:04:11.789,000] <dbg> bt_conn: bt_conn_tx_processor: TX process: conn 0x3ffcbee8 buf 0x3ffd53a4 (last)
uart:~$ ␛[8D␛[J[01:04:11.799,000] <dbg> bt_conn: tx_complete_work: conn 0x3ffcbee8
uart:~$ ␛[8D␛[J[01:04:11.799,000] <dbg> bt_conn: tx_notify: conn 0x3ffcbee8
uart:~$ ␛[8D␛[J--- 56 messages dropped ---
[01:04:11.799,000] <dbg> bt_conn: tx_notify: tx 0x3ffcd1f8 cb 0 user_data 0
uart:~$ ␛[8D␛[J[01:04:11.799,000] <dbg> bt_conn: tx_free: 0x3ffcd1f8
uart:~$ ␛[8D␛[J[01:04:11.838,000] <dbg> bt_conn: send_buf: conn 0x3ffcbee8 buf 0x3ffd4350 len 10 flags 0x02
uart:~$ ␛[8D␛[J--- 11 messages dropped ---
[01:04:11.841,000] <dbg> bt_conn: tx_complete_work: conn 0x3ffcbee8
uart:~$ ␛[8D␛[J[01:04:11.841,000] <dbg> bt_conn: tx_notify: conn 0x3ffcbee8
uart:~$ ␛[8D␛[J[01:04:11.841,000] <dbg> bt_conn: tx_notify: tx 0x3ffcd1f8 cb 0 user_data 0
uart:~$ ␛[8D␛[J--- 59 messages dropped ---
[01:04:11.842,000] <dbg> bt_conn: tx_free: 0x3ffcd1f8
uart:~$ ␛[8D␛[J[01:04:11.872,000] <dbg> bt_conn: frag_destroy: 
uart:~$ ␛[8D␛[J[01:04:11.872,000] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
uart:~$ ␛[8D␛[J[01:04:11.872,000] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
uart:~$ ␛[8D␛[J--- 9 messages dropped ---
[01:04:11.907,000] <dbg> bt_conn: tx_notify: conn 0x3ffcbee8
uart:~$ ␛[8D␛[J[01:04:11.907,000] <dbg> bt_conn: tx_notify: tx 0x3ffcd1f8 cb 0 user_data 0
uart:~$ ␛[8D␛[J[01:04:11.907,000] <dbg> bt_conn: tx_free: 0x3ffcd1f8
uart:~$ ␛[8D␛[J--- 125 messages dropped ---
[01:04:11.907,000] <dbg> bt_conn: tx_notify: raise TX IRQ
uart:~$ ␛[8D␛[J[01:04:11.936,000] <dbg> bt_l2cap_br: l2cap_br_data_pull: chan 0x3ffcc648 done
uart:~$ ␛[8D␛[J[01:04:11.936,000] <dbg> bt_conn: bt_conn_tx_processor: pop: cb 0 userdata 0
uart:~$ ␛[8D␛[J--- 13 messages dropped ---
[01:04:11.936,000] <dbg> bt_conn: bt_conn_tx_processor: TX process: conn 0x3ffcbee8 buf 0x3ffd549c (last)
uart:~$ ␛[8D␛[J[01:04:11.936,000] <dbg> bt_conn: frag_destroy: 
uart:~$ ␛[8D␛[J[01:04:11.936,000] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
uart:~$ ␛[8D␛[J--- 55 messages dropped ---
[01:04:11.936,000] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
uart:~$ ␛[8D␛[J[01:04:11.988,000] <dbg> bt_conn: bt_conn_tx_processor: TX process: conn 0x3ffcbee8 buf 0x3ffd549c (last)
uart:~$ ␛[8D␛[J[01:04:11.988,000] <dbg> bt_conn: send_buf: conn 0x3ffcbee8 buf 0x3ffd549c len 32 buf->len 32
uart:~$ ␛[8D␛[J[01:04:11.988,000] <dbg> bt_conn: conn_tx_alloc: 0x3ffcd1f8
uart:~$ ␛[8D␛[J--- 65 messages dropped ---
[01:04:11.989,000] <dbg> bt_conn: frag_destroy:
uart:~$ ␛[8D␛[J[01:04:11.989,000] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
uart:~$ ␛[8D␛[J[01:04:11.989,000] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
uart:~$ ␛[8D␛[J--- 13 messages dropped ---
[01:04:11.989,000] <dbg> bt_hci_core: tx_processor: TX process start
uart:~$ ␛[8D␛[J[01:04:12.043,000] <dbg> bt_l2cap_br: l2cap_br_data_pull: chan 0x3ffcc5a0 done
uart:~$ ␛[8D␛[J[01:04:12.043,000] <dbg> bt_conn: bt_conn_tx_processor: pop: cb 0 userdata 0
uart:~$ ␛[8D␛[J[01:04:12.044,000] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
uart:~$ ␛[8D␛[J--- 157 messages dropped ---
[01:04:12.044,000] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
uart:~$ ␛[8D␛[J[01:04:12.044,000] <dbg> bt_hci_core: tx_processor: TX process start
uart:~$ ␛[8D␛[J[01:04:12.044,000] <dbg> bt_conn: bt_conn_tx_processor: start
uart:~$ ␛[8D␛[J[01:04:12.097,000] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x3ffd4318 opcode 0x0413 len 0
uart:~$ ␛[8D␛[J--- 21 messages dropped ---
[01:04:12.098,000] <dbg> bt_conn: bt_conn_unref: handle 128 ref 3 -> 2
uart:~$ ␛[8D␛[J[01:04:12.098,000] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
uart:~$ ␛[8D␛[J[01:04:12.098,000] <dbg> bt_hci_core: rx_work_handler: buf 0x3ffd3c40 type 3 len 16
uart:~$ ␛[8D␛[J[01:04:12.133,000] <dbg> bt_conn: bt_conn_tx_processor: pop: cb 0 userdata 0
uart:~$ ␛[8D␛[J[01:04:12.133,000] <dbg> bt_conn: bt_conn_tx_processor: TX process: conn 0x3ffcbee8 buf 0x3ffd53a4 (last)
uart:~$ ␛[8D␛[J[01:04:12.133,000] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
uart:~$ ␛[8D␛[J[01:04:12.134,000] <dbg> bt_hci_core: tx_processor: TX process start
uart:~$ ␛[8D␛[J[01:04:12.134,000] <dbg> bt_conn: bt_conn_tx_processor: start
uart:~$ ␛[8D␛[J[01:04:12.134,000] <dbg> bt_conn: should_stop_tx: 0x3ffcbee8
uart:~$ ␛[8D␛[J[01:04:12.191,000] <dbg> bt_conn: tx_complete_work: conn 0x3ffcbee8
uart:~$ ␛[8D␛[J[01:04:12.191,000] <dbg> bt_conn: tx_notify: conn 0x3ffcbee8
uart:~$ ␛[8D␛[J[01:04:12.191,000] <dbg> bt_conn: tx_notify: tx 0x3ffcd1f8 cb 0 user_data 0
uart:~$ ␛[8D␛[J[01:04:12.192,000] <dbg> bt_conn: tx_free: 0x3ffcd1f8
uart:~$ ␛[8D␛[J[01:04:12.192,000] <dbg> bt_conn: bt_conn_tx_processor: no connection wants to do stuff
uart:~$ ␛[8D␛[J[01:04:12.220,000] <dbg> bt_hci_driver_esp32: hci_esp_host_rcv_pkt: host packet data:
                                              02 80 20 12 00 0e 00 01  00 05 2a 0a 00 41 00 00 |.. ..... ..*..A..
                                              00 00 00 01 02 c4 00                             |.......
uart:~$ ␛[8D␛[J[01:04:12.220,000] <dbg> bt_hci_driver_esp32: bt_esp_acl_recv: len 18
uart:~$ ␛[8D␛[J[01:04:12.220,000] <dbg> bt_hci_driver_esp32: hci_esp_host_rcv_pkt: Calling bt_recv(0x3ffd3c40)
uart:~$ ␛[8D␛[J[01:04:12.220,000] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x3ffd3c40 len 22
uart:~$ ␛[8D␛[J[01:04:12.220,000] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
uart:~$ ␛[8D␛[J[01:04:12.220,000] <dbg> bt_hci_core: rx_work_handler: buf 0x3ffd3c40 type 3 len 22
uart:~$ ␛[8D␛[J[01:04:12.220,000] <dbg> bt_hci_core: hci_acl: buf 0x3ffd3c40
uart:~$ ␛[8D␛[J[01:04:12.220,000] <dbg> bt_hci_core: hci_acl: handle 128 len 18 flags 2
uart:~$ ␛[8D␛[J[01:04:12.220,000] <dbg> bt_conn: bt_conn_ref: handle 128 ref 2 -> 3
uart:~$ ␛[8D␛[J[01:04:12.220,000] <dbg> bt_conn: wait_for_tx_work: conn 0x3ffcbee8
uart:~$ ␛[8D␛[J[01:04:12.220,000] <dbg> bt_conn: tx_complete_work: conn 0x3ffcbee8
uart:~$ ␛[8D␛[J[01:04:12.220,000] <dbg> bt_conn: tx_notify: conn 0x3ffcbee8
uart:~$ ␛[8D␛[J[01:04:12.220,000] <dbg> bt_conn: wait_for_tx_work: done
uart:~$ ␛[8D␛[J[01:04:12.220,000] <dbg> bt_conn: bt_conn_recv: handle 128 len 18 flags 02
uart:~$ ␛[8D␛[J[01:04:12.220,000] <dbg> bt_conn: bt_acl_recv: First, len 18 final 14
uart:~$ ␛[8D␛[J[01:04:12.220,000] <dbg> bt_conn: bt_acl_recv: Successfully parsed 18 byte L2CAP packet
uart:~$ ␛[8D␛[J[01:04:12.220,000] <dbg> bt_l2cap_br: l2cap_br_recv: Signaling code 0x05 ident 42 len 10
uart:~$ ␛[8D␛[J[01:04:12.220,000] <dbg> bt_l2cap_br: l2cap_br_conf_rsp: scid 0x0041 flags 0x00 result 0x00 len 4
uart:~$ ␛[8D␛[J[01:04:12.220,000] <dbg> bt_l2cap_br: l2cap_br_conf_rsp: scid 0x0041 rx MTU 196 dcid 0x0040 tx MTU 672
uart:~$ ␛[8D␛[J[01:04:12.220,000] <dbg> bt_avdtp: bt_avdtp_l2cap_connected: chan 0x3ffcc450 session 0x3ffcc450
uart:~$ ␛[8D␛[J[i] Successfully connected to AVDTP layer!
uart:~$ ␛[8D␛[J[01:04:12.220,000] <dbg> bt_conn: bt_conn_unref: handle 128 ref 3 -> 2
uart:~$ ␛[8D␛[Juart:~$ ␛[8D␛[Juart:~$ ␛[8D␛[J--- 33 messages dropped ---
[01:04:13.946,000] <dbg> bt_l2cap_br: l2cap_br_data_pull: last frag, removing 0x3ffd53a4
uart:~$ ␛[8D␛[J[01:04:13.946,000] <dbg> bt_l2cap_br: l2cap_br_data_pull: chan 0x3ffcc5a0 done
uart:~$ ␛[8D␛[J[01:04:13.946,000] <dbg> bt_conn: bt_conn_tx_processor: pop: cb 0 userdata 0
uart:~$ ␛[8D␛[J[01:04:13.946,000] <dbg> bt_conn: bt_conn_tx_processor: TX process: conn 0x3ffcbee8 buf 0x3ffd53a4 (last)
uart:~$ ␛[8D␛[J--- 3 messages dropped ---
[01:04:13.946,000] <dbg> bt_conn: send_buf: conn 0x3ffcbee8 buf 0x3ffd53a4 len 12 buf->len 12
uart:~$ ␛[8D␛[J[01:04:13.946,000] <dbg> bt_conn: conn_tx_alloc: 0x3ffcd1ec
uart:~$ ␛[8D␛[J[01:04:13.946,000] <dbg> bt_conn: send_buf: move 0x3ffd53a4 ref in
uart:~$ ␛[8D␛[J[01:04:13.946,000] <dbg> bt_buf: bt_buf_make_view: make-view 0x3ffd4350 viewsize 12 meta 0x3ffcd1dc
uart:~$ ␛[8D␛[J[01:04:13.946,000] <dbg> bt_conn: get_data_frag: get-acl-frag: outside 0x3ffd53a4 window 0x3ffd4350 size 12
uart:~$ ␛[8D␛[J[01:04:13.946,000] <dbg> bt_conn: send_buf: send frag: buf 0x3ffd53a4 len 12
uart:~$ ␛[8D␛[J[01:04:13.946,000] <dbg> bt_conn: send_buf: conn 0x3ffcbee8 buf 0x3ffd4350 len 12 flags 0x02
uart:~$ ␛[8D␛[J[01:04:13.946,000] <dbg> bt_hci_core: bt_send: buf 0x3ffd4350 len 16 type 2
uart:~$ ␛[8D␛[J[01:04:13.946,000] <dbg> bt_hci_driver_esp32: bt_esp32_send: buf 0x3ffd4350 type 2 len 16
uart:~$ ␛[8D␛[J[01:04:13.946,000] <dbg> bt_hci_driver_esp32: bt_esp32_send: Final HCI buffer:
                                              02 80 00 0c 00 08 00 01  00 07 06 04 00 41 00 40 |........ .....A.@
                                              00                                               |.
uart:~$ ␛[8D␛[J[01:04:13.946,000] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
uart:~$ ␛[8D␛[J[01:04:13.946,000] <dbg> bt_hci_core: tx_processor: TX process start
uart:~$ ␛[8D␛[J[01:04:13.946,000] <dbg> bt_conn: bt_conn_tx_processor: start
uart:~$ ␛[8D␛[J[01:04:13.946,000] <dbg> bt_conn: should_stop_tx: 0x3ffcbee8
uart:~$ ␛[8D␛[J[01:04:13.946,000] <dbg> bt_conn: should_stop_tx: No more data for 0x3ffcbee8
uart:~$ ␛[8D␛[J[01:04:13.946,000] <dbg> bt_conn: bt_conn_tx_processor: processing conn 0x3ffcbee8
uart:~$ ␛[8D␛[J[01:04:13.946,000] <dbg> bt_l2cap_br: l2cap_br_data_pull: nothing to send on this conn
uart:~$ ␛[8D␛[J[01:04:13.946,000] <dbg> bt_conn: bt_conn_tx_processor: no buf returned
uart:~$ ␛[8D␛[J[01:04:13.966,000] <dbg> bt_hci_driver_esp32: hci_esp_host_rcv_pkt: host packet data:
                                              04 13 05 01 80 00 01 00                          |........
uart:~$ ␛[8D␛[J[01:04:13.966,000] <dbg> bt_hci_driver_esp32: bt_esp_evt_recv: len 5
uart:~$ ␛[8D␛[J[01:04:13.966,000] <dbg> bt_hci_driver_esp32: hci_esp_host_rcv_pkt: Calling bt_recv(0x3ffd40f4)
uart:~$ ␛[8D␛[J[01:04:13.966,000] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x3ffd40f4 len 7
uart:~$ ␛[8D␛[J[01:04:13.966,000] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
uart:~$ ␛[8D␛[J[01:04:13.966,000] <dbg> bt_hci_core: hci_num_completed_packets: handle 128 count 1
uart:~$ ␛[8D␛[J[01:04:13.966,000] <dbg> bt_conn: bt_conn_ref: handle 128 ref 2 -> 3
uart:~$ ␛[8D␛[J[01:04:13.966,000] <dbg> bt_conn: bt_conn_unref: handle 128 ref 3 -> 2
uart:~$ ␛[8D␛[J[01:04:13.966,000] <dbg> bt_conn: tx_complete_work: conn 0x3ffcbee8
uart:~$ ␛[8D␛[J[01:04:13.966,000] <dbg> bt_conn: tx_notify: conn 0x3ffcbee8
uart:~$ ␛[8D␛[J[01:04:13.966,000] <dbg> bt_conn: tx_notify: tx 0x3ffcd1ec cb 0 user_data 0
uart:~$ ␛[8D␛[J[01:04:13.966,000] <dbg> bt_conn: tx_free: 0x3ffcd1ec
uart:~$ ␛[8D␛[J[01:04:13.966,000] <dbg> bt_conn: tx_notify: raise TX IRQ
uart:~$ ␛[8D␛[J[01:04:13.966,000] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
uart:~$ ␛[8D␛[J[01:04:13.966,000] <dbg> bt_hci_core: tx_processor: TX process start
uart:~$ ␛[8D␛[J[01:04:13.967,000] <dbg> bt_conn: bt_conn_tx_processor: start
uart:~$ ␛[8D␛[J[01:04:13.967,000] <dbg> bt_conn: bt_conn_tx_processor: no connection wants to do stuff
uart:~$ ␛[8D␛[Juart:~$ ␛[8D␛[Juart:~$ ␛[8D␛[J[01:04:16.785,000] <dbg> bt_conn: deferred_work: conn 0x3ffcbee8
uart:~$ ␛[8D␛[Juart:~$ ␛[8D␛[J--- 4 messages dropped ---
[01:04:18.332,000] <dbg> bt_hci_core: hci_disconn_complete_prio: status 0x00 handle 128 reason 0x13
uart:~$ ␛[8D␛[J[01:04:18.332,000] <dbg> bt_conn: bt_conn_ref: handle 128 ref 2 -> 3
uart:~$ ␛[8D␛[J[01:04:18.332,000] <dbg> bt_conn: bt_conn_set_state: connected -> disconnect-complete
uart:~$ ␛[8D␛[J[01:04:18.332,000] <dbg> bt_conn: process_unack_tx: 0x3ffcbee8
uart:~$ ␛[8D␛[J[01:04:18.332,000] <dbg> bt_conn: bt_conn_unref: handle 128 ref 3 -> 2
uart:~$ ␛[8D␛[J[01:04:18.332,000] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
uart:~$ ␛[8D␛[J[01:04:18.332,000] <dbg> bt_hci_core: rx_work_handler: buf 0x3ffd3c40 type 1 len 6
uart:~$ ␛[8D␛[J[01:04:18.332,000] <dbg> bt_hci_core: hci_event: event 0x05
uart:~$ ␛[8D␛[J[01:04:18.332,000] <dbg> bt_hci_core: hci_disconn_complete: status 0x00 handle 128 reason 0x13
uart:~$ ␛[8D␛[J[01:04:18.332,000] <dbg> bt_conn: bt_conn_ref: handle 128 ref 2 -> 3
uart:~$ ␛[8D␛[J[01:04:18.332,000] <dbg> bt_conn: bt_conn_set_state: disconnect-complete -> disconnected
uart:~$ ␛[8D␛[J[01:04:18.332,000] <dbg> bt_conn: wait_for_tx_work: conn 0x3ffcbee8
uart:~$ ␛[8D␛[J[01:04:18.332,000] <dbg> bt_conn: tx_complete_work: conn 0x3ffcbee8
uart:~$ ␛[8D␛[J[01:04:18.332,000] <dbg> bt_conn: tx_notify: conn 0x3ffcbee8
uart:~$ ␛[8D␛[J[01:04:18.332,000] <dbg> bt_conn: wait_for_tx_work: done
uart:~$ ␛[8D␛[J[01:04:18.332,000] <dbg> bt_conn: bt_conn_set_state: trigger disconnect work
uart:~$ ␛[8D␛[J[01:04:18.332,000] <dbg> bt_conn: bt_conn_unref: handle 128 ref 3 -> 2
uart:~$ ␛[8D␛[J[01:04:18.332,000] <dbg> bt_conn: deferred_work: conn 0x3ffcbee8
uart:~$ ␛[8D␛[J[01:04:18.332,000] <dbg> bt_l2cap_br: bt_l2cap_br_chan_del: conn 0x3ffcbee8 chan 0x3ffcc5a0
uart:~$ ␛[8D␛[J[01:04:18.332,000] <dbg> bt_l2cap_br: l2cap_br_disconnected: ch 0x3ffcc5a0 cid 0x0001
uart:~$ ␛[8D␛[JDisconnected (reason 0x13)
uart:~$ ␛[8D␛[J[01:04:18.333,000] <dbg> bt_conn: bt_conn_unref: handle 128 ref 2 -> 1
uart:~$ ␛[8D␛[J[01:04:18.333,000] <dbg> bt_conn: bt_conn_unref: handle 128 ref 1 -> 0

Here is a screenshot from my Kali VM: tempsnip

This is what my main.c looks like :

#include <zephyr/types.h>
#include <stddef.h>
#include <string.h>
#include <errno.h>
#include <zephyr/libsbc/sbc.h>
#include <zephyr/sys/printk.h>
#include <zephyr/sys/byteorder.h>
#include <zephyr/kernel.h>
#include <zephyr/bluetooth/bluetooth.h>
#include <zephyr/bluetooth/conn.h>
#include <zephyr/bluetooth/l2cap.h>
#include <zephyr/bluetooth/classic/sdp.h>
#include <zephyr/bluetooth/classic/a2dp.h>
#include <zephyr/bluetooth/classic/rfcomm.h>
#include <zephyr/bluetooth/classic/a2dp_codec_sbc.h>
#include "app_connect.h"
#include "a2dp_media_48KHz_1ksin.h"

#define SDP_CLIENT_USER_BUF_LEN     512U
NET_BUF_POOL_FIXED_DEFINE(app_sdp_client_pool, CONFIG_BT_MAX_CONN,
              SDP_CLIENT_USER_BUF_LEN, 8, NULL);

static uint8_t app_sdp_a2sink_user(struct bt_conn *conn, struct bt_sdp_client_result *result);

static void a2dp_playback_timeout_handler(struct k_timer *timer);
K_TIMER_DEFINE(a2dp_player_timer, a2dp_playback_timeout_handler, NULL);

#define APPL_A2DP_MTU   (672U)
#define DEFAULT_BIT_RATE (328u)

static uint32_t a2dp_src_sf;

static int64_t ref_time;
static uint32_t a2dp_src_missed_count;
static volatile uint8_t a2dp_src_playback;
static int tone_index;
uint8_t a2dp_src_nc;

#define A2DP_SBC_BLOCK_MAX (512U)
uint32_t audio_time_interval; /* ms */
uint32_t audio_frame_sample_count;
uint8_t a2dp_pcm_buffer[1920u]; /* 10ms max packet pcm data size. the max is 480 * 2 * 2 */
uint8_t a2dp_sbc_encode_buffer_frame[A2DP_SBC_BLOCK_MAX];
struct sbc_encoder encoder;
uint32_t send_samples_count;
uint16_t send_count;

#define A2DP_SRC_PERIOD_MS  10

struct bt_a2dp *source_a2dp;
struct bt_a2dp_ep *sink_a2dp_ep;
struct bt_a2dp_stream *bt_a2dp_stream_handle;
BT_A2DP_SBC_SOURCE_EP_DEFAULT(a2dp_source_ep);

struct k_work_delayable discover_pipes;

static void stream_configured(struct bt_a2dp_stream *stream) {
    printk("Streaming successfully configurated!");
}

static void stream_etablished(struct bt_a2dp_stream *stream) {
    printk("Streaming pipe successfully etablished!");
}

static void stream_released(struct bt_a2dp_stream *stream) {
    printk("Streaming pipe successfully released!");
}

static void stream_started(struct bt_a2dp_stream *stream) {
    printk("Streaming pipe successfully started");
}

struct bt_a2dp_stream_ops stream_ops = {
    .configured = stream_configured,
    .established = stream_etablished,
    .released = stream_released,
    .started = stream_started,
};

uint8_t discover_sep(struct bt_a2dp *a2dp, struct bt_a2dp_ep_info *info, struct bt_a2dp_ep **ep) {
    printk("Discovering SEPs !");

    if (info != NULL) {
        if (ep != NULL) {
            sink_a2dp_ep = *ep;
        }
        return BT_A2DP_DISCOVER_EP_STOP;
    }

    return BT_A2DP_DISCOVER_EP_STOP;
}

static void call_discover_seps_handler(struct k_work *work) {
    int ret;

    struct bt_a2dp_ep_info ep_info;
    struct bt_avdtp_sep_info *sep_info;

    struct bt_a2dp_discover_param discovery_param = {
        .cb = discover_sep,
        .info = ep_info,
        .seps_info = sep_info,
        .sep_count = 1,
    };

    ret = bt_a2dp_discover(source_a2dp, &discovery_param);
    if (ret) {
        printk("Failed to start SEP discovery: %d\n", ret);
    }   
}

static uint8_t *a2dp_pl_produce_media(uint32_t a2dp_src_num_samples)
{
    uint8_t *media = NULL;
    uint16_t  medialen;

    /* Music Audio is Stereo */
    medialen = (a2dp_src_num_samples * a2dp_src_nc * 2);

    /* For mono or dual configuration, skip alternative samples */
    if (1 == a2dp_src_nc) {
        uint16_t index;

        media = (uint8_t *)&a2dp_pcm_buffer[0];

        for (index = 0; index < a2dp_src_num_samples; index++) {
            media[(2 * index)] = *((uint8_t *)beethoven + tone_index);
            media[(2 * index) + 1] = *((uint8_t *)beethoven + tone_index + 1);
            /* Update the tone index */
            tone_index += 4u;
            if (tone_index >= sizeof(beethoven)) {
                tone_index = 0U;
            }
        }
    } else {
        if ((tone_index + (a2dp_src_num_samples << 2)) > sizeof(beethoven)) {
            media = (uint8_t *)&a2dp_pcm_buffer[0];
            memcpy(media, ((uint8_t *)beethoven + tone_index),
                sizeof(beethoven) - tone_index);
            memcpy(&media[sizeof(beethoven) - tone_index],
                ((uint8_t *)beethoven),
                ((a2dp_src_num_samples << 2) - (sizeof(beethoven) - tone_index)));
            /* Update the tone index */
            tone_index = ((a2dp_src_num_samples << 2) -
                (sizeof(beethoven) - tone_index));
        } else {
            media = ((uint8_t *)beethoven + tone_index);
            /* Update the tone index */
            tone_index += (a2dp_src_num_samples << 2);
            if (tone_index >= sizeof(beethoven)) {
                tone_index = 0U;
            }
        }
    }

    return media;
}

static void a2dp_playback_timeout_handler(struct k_timer *timer)
{
    int64_t period_ms;
    uint32_t a2dp_src_num_samples;
    uint8_t *pcm_data;
    uint8_t index;
    uint32_t pcm_frame_size;
    uint32_t pcm_frame_samples;
    uint32_t encoded_frame_size;
    uint8_t *net_buffer;
    struct net_buf *buf;
    uint32_t sample_count = 0;
    uint8_t frame_num = 0;
    int ret;
    // struct bt_a2dp_codec_sbc_media_packet_hdr *sbc_hdr;
    uint8_t *sbc_hdr;
    int err;

    /* If stopped then return */
    if (0U == a2dp_src_playback) {
        return;
    }

    period_ms = k_uptime_delta(&ref_time);

    NET_BUF_POOL_DEFINE(pool_buf, 0, 1000, 0, NULL);
    buf = net_buf_alloc(&pool_buf, K_NO_WAIT);
    if (buf == NULL) {
        return;
    }
    sbc_hdr = net_buf_add(buf, sizeof(uint8_t));
    /* Get the number of samples */
    a2dp_src_num_samples = (uint16_t)((period_ms * a2dp_src_sf) / 1000);
    a2dp_src_missed_count += (uint32_t)((period_ms * a2dp_src_sf) % 1000);

    /* Raw adjust for the drift */
    while (a2dp_src_missed_count >= (1000 * audio_frame_sample_count)) {
        a2dp_src_num_samples += audio_frame_sample_count;
        a2dp_src_missed_count -= (1000 * audio_frame_sample_count);
    }

    pcm_data = a2dp_pl_produce_media(a2dp_src_num_samples);
    if (pcm_data == NULL) {
        return;
    }

    pcm_frame_size = sbc_frame_bytes(&encoder);
    pcm_frame_samples = sbc_frame_samples(&encoder);
    encoded_frame_size = sbc_frame_encoded_bytes(&encoder);
    for (index = 0; index < (a2dp_src_num_samples / audio_frame_sample_count); index++) {
        net_buffer = net_buf_tail(buf);
        if (buf->len + encoded_frame_size > bt_a2dp_get_mtu(bt_a2dp_stream_handle)) {
            printk("mtu error");
            return;
        }

        err = sbc_encode(&encoder,
                (uint8_t *)&pcm_data[index * pcm_frame_size],
                encoded_frame_size, &net_buffer[0]);
        if (err) {
            printk("sbc encode fail");
            continue;
        }
        buf->len += encoded_frame_size;
        sample_count += pcm_frame_samples;
        frame_num++;
    }

    *sbc_hdr = BT_A2DP_SBC_MEDIA_HDR_ENCODE(frame_num, 0, 0, 0);

    ret = bt_a2dp_stream_send(bt_a2dp_stream_handle, buf, send_count, send_samples_count);
    if (ret < 0) {
        printk("Failed to send SBC audio data on streams(%d)\n", ret);
        net_buf_unref(buf);
    } else {
        send_count++;
        send_samples_count += sample_count;
    }
}

static void music_control_a2dp_start(void)
{
    /* Start Audio Source */
    a2dp_src_playback = 1U;
    audio_frame_sample_count = sbc_frame_samples(&encoder);

    /* calculate the interval that contains multiple of frame. default is 10ms */
    audio_time_interval = ((10 * a2dp_src_sf / 1000) / audio_frame_sample_count);
    audio_time_interval = audio_time_interval * audio_frame_sample_count * 1000 / a2dp_src_sf;
    k_uptime_delta(&ref_time);
    k_timer_start(&a2dp_player_timer, K_MSEC(audio_time_interval), K_MSEC(audio_time_interval));
}

static struct bt_sdp_discover_params discov_a2dp_sink = {
    .uuid = BT_UUID_DECLARE_16(BT_SDP_AUDIO_SINK_SVCLASS),
    .func = app_sdp_a2sink_user,
    .pool = &app_sdp_client_pool,
};

static uint8_t app_sdp_a2sink_user(struct bt_conn *conn,
               struct bt_sdp_client_result *result)
{
    uint16_t param;
    int res;

    if ((result) && (result->resp_buf)) {
        printk("sdp success callback\r\n");
        res = bt_sdp_get_proto_param(result->resp_buf, BT_SDP_PROTO_L2CAP, &param);
        if (res < 0) {
            printk("PSM is not found\r\n");
            return BT_SDP_DISCOVER_UUID_CONTINUE;
        }
        if (param == BT_UUID_AVDTP_VAL) {
            printk("A2DP Service found. Connecting ...\n");
            source_a2dp = bt_a2dp_connect(default_conn);
            if (source_a2dp == NULL) {
                printk("fail to connect a2dp\r\n");
            }
            return BT_SDP_DISCOVER_UUID_STOP;
        }
        return BT_SDP_DISCOVER_UUID_CONTINUE;
    }

    printk("sdp fail callback\r\n");
    return BT_SDP_DISCOVER_UUID_CONTINUE;
}

void app_sdp_discover_a2dp_sink(void)
{
    int res;

    res = bt_sdp_discover(default_conn, &discov_a2dp_sink);
    if (res) {
        printk("SDP discovery failed: result\r\n");
    } else {
        printk("SDP discovery started\r\n");
    }
}

static void a2dp_connected(struct bt_a2dp *a2dp, int err) {

    if(!err) {

        printk("[i] Successfully connected to AVDTP layer!\n");

        k_work_schedule(&discover_pipes, K_SECONDS(10));

        // struct bt_a2dp_stream bt_a2dp_stream_handle = {
        //  .local_ep = &a2dp_source_ep,
        //  .remote_ep = remote_a2dp_endpoint,
        //  .remote_ep_id = 0,
        //  .ops = &stream_ops,
        //  .a2dp = source_a2dp,
        //  .codec_config = bt_a2dp_ep_cap_iea2dp_source_ep
        // };

        // int ret;

        // ret = bt_a2dp_stream_establish(remote_a2dp_endpoint->stream);

        // if(ret){
        //  printk("Unable to send AVDTP_OPEN command");
        // } else {
        //  music_control_a2dp_start();
        // }

    } else {
        if (source_a2dp != NULL) {
            source_a2dp = NULL;
        }
        printk("[E] Unable to connect to AVDTP layer (Error: %d).\n", err);
    }
}

static void a2dp_disconnected(struct bt_a2dp *a2dp) {
    // int ret;

    printk("[i] Device disconnected from A2DP profile!\n");
    k_work_cancel_delayable(&discover_pipes);
    // a2dp_src_playback = 0U;
    // /* stop timer */
    // k_timer_stop(&a2dp_player_timer);
    // printk("a2dp disconnected\r\n");

    // ret = bt_a2dp_stream_release(bt_a2dp_stream_handle);

    // if(ret){
    //  printk("Unable to send AVDTP_OPEN command");
    // }
}

// static int a2dp_configuration(struct bt_a2dp *a2dp, struct bt_a2dp_ep *ep, struct bt_a2dp_codec_cfg *codec_cfg, struct bt_a2dp_stream **stream, uint8_t *rsp_err_code) {
//  struct bt_a2dp_codec_sbc_params *config = (struct bt_a2dp_codec_sbc_params *) &codec_cfg->codec_config->codec_ie[0];

//  a2dp_src_sf = bt_a2dp_sbc_get_sampling_frequency(config);
//  a2dp_src_nc = bt_a2dp_sbc_get_channel_num(config);

//  sbc_setup_encoder(&encoder, a2dp_src_sf, BT_A2DP_SBC_CHAN_MODE(config), BT_A2DP_SBC_BLK_LEN(config), BT_A2DP_SBC_SUB_BAND(config), BT_A2DP_SBC_ALLOC_MTHD(config), DEFAULT_BIT_RATE);
//  // bt_a2dp_stream_start(bt_a2dp_stream_handle);
//  // printk("a2dp start playing\r\n");

//  stream = &bt_a2dp_stream_handle;

//  return 0;
// }

static struct bt_a2dp_cb bt_a2dp_callbacks = {
    .connected = a2dp_connected,
    .disconnected = a2dp_disconnected,
    //.config_req = a2dp_configuration,
};

static void app_a2dp_init(void) {
    bt_a2dp_register_ep(&a2dp_source_ep, BT_AVDTP_AUDIO, BT_AVDTP_SOURCE);
    bt_a2dp_register_cb(&bt_a2dp_callbacks);
}

static void bt_ready(int err)
{
    if (err) {
        printk("Bluetooth init failed (err %d)\n", err);
        return;
    }

    printk("Bluetooth initialized\n");

    app_connect_init();
    app_a2dp_init();

    k_work_init_delayable(&discover_pipes, call_discover_seps_handler);

}

int main(void)
{
    int err;

    err = bt_enable(bt_ready);
    if (err) {
        printk("Bluetooth init failed (err %d)\n", err);
    }

    return err;
}

Environment (please complete the following information):

Thank you in advance for your assistance! 😄

sylvioalves commented 2 months ago

ESP32 in Zephyr only supports BLE, not BT classic. Converting this from BUG to Enhancement accordingly.

xG3nesis commented 1 month ago

I must confess, @sylvioalves, your answer has left me a bit underwhelmed. So, I have a trio of puzzlers for you:

  1. If BT Classic isn't supported, how come my ESP32-PICO-D4 is happily chatting away via a simple Bluetooth RFCOMM serial connection? Magic? rfcomm_prf

  2. If BT Classic isn't part of the deal, why not shout it from the rooftops in the Bluetooth documentation?

  3. And lastly, if BT Classic is out of the picture, why didn't your post (updated on the 17th of june) include a neon sign making it clear which Bluetooth flavor (Classic or BLE) we're working with?

sylvioalves commented 1 month ago

Hi @xG3nesis, nice to hear that it is working as we have not yet tested it.

Let me tell you the background and reasoning that I consider it is not supported (yet).

When we started working on ESP32xx Bluetooth support in Zephyr, BT classic was still marked as "EXPERIMENTAL". We then decided to only add BLE support. It means we implemented and tested only BLE sample codes (and provide necessary changes to make it work). BT classic support was not handled in any way, neither checking nor testing. Up to now, we have not yet worked on it. That is the reason I initially considered this is not implemented. So it is really interesting to see it is already in place as you mentioned before.

For item 3) of the development overview, you are correct, we could have split BT/BLE in different lines to make it clear.

Anyway, thanks for enlightening me with kindly words about BT classic. I still do not have the solution for the issue though.

sylvioalves commented 1 month ago

It is also worth mentioning that there are some hidden BT configurations in ESP32 adapter. Those configurations (at least a few) could be related to BT classic. Take a look in this file to evaluate as well: https://github.com/zephyrproject-rtos/hal_espressif/blob/zephyr/zephyr/esp32/include/bt/esp_bt.h#L156

rftafas commented 1 month ago

Up to now, we have not yet worked on it. That is the reason I initially considered this is not implemented. So it is really interesting to see it is already in place as you mentioned before.

I'd like also to add that BT Classic is not on our roadmap either. But, being open source, if the community decides to go for it, we will help as much as possible (same applies to several other subsystems/features).