Bluetooth: Disconnection due to "No pending ATT request"

[cvinayak]

Describe the bug

LE Audio test ./tests/bsim/bluetooth/audio/test_scripts/cap_unicast_ac_11_ii.sh fails with following error:

d_00: @00:00:04.008515  (CPU:0): [00:00:04.008,514] <dbg> bt_iso: hci_le_set_cig_params: id 0, latency C to P 8, latency P to C 8, interval C to P 7500, interval P to C 7500, sca 0, packing 0, framing 0, num_cis 2
d_00: @00:00:04.008515  (CPU:0): [00:00:04.008,514] <dbg> bt_iso: hci_le_set_cig_params: [0]: id 0, c_phy 2, c_sdu 26, c_rtn 2, p_phy 2, p_sdu 26, p_rtn 2
d_00: @00:00:04.008515  (CPU:0): [00:00:04.008,514] <dbg> bt_iso: hci_le_set_cig_params: [1]: id 1, c_phy 2, c_sdu 26, c_rtn 2, p_phy 2, p_sdu 26, p_rtn 2
d_00: @00:00:04.008515  (CPU:0): Starting 4 streams for ac_11_ii
d_00: @00:00:04.008515 ERROR: (WEST_TOPDIR/zephyr/tests/bsim/bluetooth/audio/src/cap_initiator_unicast_test.c:1164): No sink[1][0] endpoint available
d_00: @00:00:04.008515  The TESTCASE FAILED (test return code 2)

To Reproduce

Update as below:

diff --git a/samples/bluetooth/hci_ipc/nrf5340_cpunet_iso-bt_ll_sw_split.conf b/samples/bluetooth/hci_ipc/nrf5340_cpunet_iso-bt_ll_sw_split.conf
index 21c5ac86e7c..2d956bfe62e 100644
--- a/samples/bluetooth/hci_ipc/nrf5340_cpunet_iso-bt_ll_sw_split.conf
+++ b/samples/bluetooth/hci_ipc/nrf5340_cpunet_iso-bt_ll_sw_split.conf
@@ -19,6 +19,7 @@ CONFIG_BT_BUF_EVT_RX_SIZE=255
 CONFIG_BT_BUF_ACL_RX_SIZE=255
 CONFIG_BT_BUF_ACL_TX_SIZE=251
 CONFIG_BT_BUF_CMD_TX_SIZE=255
+CONFIG_BT_BUF_ACL_TX_COUNT=3
 
 # Host and Controller common dependencies
 CONFIG_BT_BROADCASTER=y

Build:

BOARD=nrf5340bsim/nrf5340/cpuapp ./tests/bsim/bluetooth/audio/compile.sh

Execute:

BOARD=nrf5340bsim/nrf5340/cpuapp ./tests/bsim/bluetooth/audio/test_scripts/cap_unicast_ac_11_ii.sh

Expected behavior

No disconnection and test passes.

Impact

Showstopper

Logs and console output

Environment (please complete the following information):

• OS: Linux
• Toolchain: Zephyr SDK 0.16.5-1
• Commit SHA or Version used: fa45beb

Additional context

Full log:

log.txt

[Thalley]

I'll try to reproduce locally and then determiner if this is a controller, host, audio or test bug.

The ATT disconnect behavior comes from #83222

[Thalley]

While the test case reports failure in

d_00: @00:00:04.008515 ERROR: (WEST_TOPDIR/zephyr/tests/bsim/bluetooth/audio/src/cap_initiator_unicast_test.c:1164): No sink[1][0] endpoint available

The actual failure is that discovery fails:

d_00: @00:00:04.007868  (CPU:0): Source discover complete
d_00: @00:00:04.008515  (CPU:0): Failed to discover CAS: -107
d_00: @00:00:04.008515  (CPU:0): Failed to discover sink: -107
d_00: @00:00:04.008515  (CPU:0): Failed to discover sink: -107

because there's a disconnect

d_00: @00:00:03.718508  (CPU:0): [00:00:03.718,505] <dbg> bt_bap_unicast_client: unicast_client_pacs_context_discover: conn 0x84f37c0
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <wrn> bt_att: att_handle_rsp: No pending ATT request
d_00: @00:00:03.858744  (CPU:0): [00:00:03.858,734] <dbg> bt_bap_unicast_client: unicast_client_pacs_context_discover_cb: conn 0x84f37c0 attr 0xe82fcf70 handle 0x0024 dir sink
d_00: @00:00:03.860331  (CPU:0): [00:00:03.860,321] <dbg> bt_bap_unicast_client: unicast_client_disconnected: conn 0x84f38b0 reason 0x16
d_00: @00:00:03.860331  (CPU:0): [00:00:03.860,321] <dbg> bt_bap_unicast_client: unicast_client_ep_reset: conn 0x84f38b0
d_00: @00:00:03.860331  (CPU:0): [00:00:03.860,321] <dbg> bt_bap_unicast_client: unicast_client_reset: ep 0x852fa68
d_00: @00:00:03.860331  (CPU:0): [00:00:03.860,321] <dbg> bt_bap_unicast_client: unicast_client_ep_set_status: ep 0x852fa68 handle 0x0000 id 0x00 dir Unknown state idle -> idle
d_00: @00:00:03.860331  (CPU:0): [00:00:03.860,321] <dbg> bt_bap_unicast_client: unicast_client_reset: ep 0x852fc3c
d_00: @00:00:03.860331  (CPU:0): [00:00:03.860,321] <dbg> bt_bap_unicast_client: unicast_client_ep_set_status: ep 0x852fc3c handle 0x0000 id 0x00 dir Unknown state idle -> idle
d_00: @00:00:03.860331  (CPU:0): [00:00:03.860,321] <dbg> bt_bap_unicast_client: unicast_client_reset: ep 0x852fe10
d_00: @00:00:03.860331  (CPU:0): [00:00:03.860,321] <dbg> bt_bap_unicast_client: unicast_client_ep_set_status: ep 0x852fe10 handle 0x0000 id 0x00 dir Unknown state idle -> idle
d_00: @00:00:03.860331  (CPU:0): [00:00:03.860,321] <dbg> bt_bap_unicast_client: unicast_client_reset: ep 0x852ffe4
d_00: @00:00:03.860331  (CPU:0): [00:00:03.860,321] <dbg> bt_bap_unicast_client: unicast_client_ep_set_status: ep 0x852ffe4 handle 0x0000 id 0x00 dir Unknown state idle -> idle
d_00: @00:00:03.860331  (CPU:0): [00:00:03.860,321] <dbg> bt_has: disconnected: conn 0x84f38b0 reason 22

[Thalley]

Enabling CONFIG_BT_ATT_LOG_LEVEL_DBG=y gives

d_00: @00:00:03.718508  (CPU:0): [00:00:03.718,505] <dbg> bt_att: bt_att_req_alloc: Timeout discarded. No blocking on bt_recv thread.
d_00: @00:00:03.718508  (CPU:0): [00:00:03.718,505] <dbg> bt_att: bt_att_req_alloc: req 0x859f5e0
d_00: @00:00:03.718508  (CPU:0): [00:00:03.718,505] <dbg> bt_att: bt_att_req_send: conn 0x84f37c0 req 0x859f5e0
d_00: @00:00:03.718508  (CPU:0): [00:00:03.718,505] <dbg> bt_att: bt_att_chan_req_send: req 0x859f5e0
d_00: @00:00:03.718508  (CPU:0): [00:00:03.718,505] <dbg> bt_att: chan_req_send: chan 0x859f784 req 0x859f5e0 len 7
d_00: @00:00:03.718508  (CPU:0): [00:00:03.718,505] <dbg> bt_att: bt_att_chan_send: chan 0x859f784 flags 1 code 0x08
d_00: @00:00:03.718508  (CPU:0): [00:00:03.718,505] <dbg> bt_att: chan_send: code 0x08
d_00: @00:00:03.718508  (CPU:0): [00:00:03.718,505] <dbg> bt_att: att_tx_destroy: 0x859fbb8
d_00: @00:00:03.718508  (CPU:0): [00:00:03.718,505] <dbg> bt_att: att_on_sent_cb: opcode 0x8
d_00: @00:00:03.718508  (CPU:0): [00:00:03.718,505] <dbg> bt_att: att_on_sent_cb: UATT bearer, calling att_sent
d_00: @00:00:03.718508  (CPU:0): [00:00:03.718,505] <dbg> bt_att: att_sent: conn 0x84f37c0 chan 0x859f788
d_00: @00:00:03.718508  (CPU:0): [00:00:03.718,505] <dbg> bt_att: bt_att_sent: chan 0x859f784
d_00: @00:00:03.718508  (CPU:0): [00:00:03.718,505] <dbg> bt_att: chan_rebegin_att_timeout: chan 0x859f784 chan->req 0x859f5e0
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_att: bt_att_recv: Received ATT chan 0x859f8bc code 0x09 len 120
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_att: att_handle_read_type_rsp: 
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_att: att_handle_rsp: chan 0x859f8bc err 0 len 120: 070200200300052a05000a0600292b07000208002a2b0a00020b00002a0c00020d00012a0e00020f00042a1100041200062a1400121500c92b17001a1800ca2b
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <wrn> bt_att: att_handle_rsp: No pending ATT request
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_att: att_disconnect: ATT disconnecting device D5:90:2D:9B:9A:EC (random)
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_att: bt_att_disconnected: chan 0x859f8c0 cid 0x0004
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_att: att_chan_detach: chan 0x859f8bc
d_00: @00:00:03.858744  (CPU:0): [00:00:03.858,734] <dbg> bt_att: bt_att_recv: Received ATT chan 0x859f784 code 0x09 len 120
d_00: @00:00:03.858744  (CPU:0): [00:00:03.858,734] <dbg> bt_att: att_handle_read_type_rsp: 
d_00: @00:00:03.858744  (CPU:0): [00:00:03.858,734] <dbg> bt_att: att_handle_rsp: chan 0x859f784 err 0 len 120: 070200200300052a05000a0600292b07000208002a2b0a00020b00002a0c00020d00012a0e00020f00042a1100041200062a1400121500c92b17001a1800ca2b
d_00: @00:00:03.858744  (CPU:0): [00:00:03.858,734] <dbg> bt_att: bt_att_req_free: req 0x859f5e0

So ATT channel 0x859f784 sends a BT_ATT_OP_READ_TYPE_REQ (0x08) but then somehow ATT channel 0x859f8bc receives the BT_ATT_OP_READ_TYPE_RSP (0x09) first, and then ATT channel 0x859f784 correctly receives the response.

So somehow the response is received on multiple ATT channels

[Thalley]

Enabling CONFIG_BT_L2CAP_LOG_LEVEL_DBG=y shows that we actually "receive" a "response" from both connected devices:

d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 121 conn 0x84f48b0
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x85a09c0 len 121
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_att: bt_att_recv: Received ATT chan 0x85a09bc code 0x09 len 120
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_att: att_handle_read_type_rsp: 
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_att: att_handle_rsp: chan 0x85a09bc err 0 len 120: 070200200300052a05000a0600292b07000208002a2b0a00020b00002a0c00020d00012a0e00020f00042a1100041200062a1400121500c92b17001a1800ca2b
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <wrn> bt_att: att_handle_rsp: No pending ATT request
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_att: att_disconnect: ATT disconnecting device D5:90:2D:9B:9A:EC (random)
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_att: bt_att_disconnected: chan 0x85a09c0 cid 0x0004
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_att: att_chan_detach: chan 0x85a09bc
d_00: @00:00:03.858744  (CPU:0): [00:00:03.858,734] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 121 conn 0x84f47c0
d_00: @00:00:03.858744  (CPU:0): [00:00:03.858,734] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x85a0888 len 121
d_00: @00:00:03.858744  (CPU:0): [00:00:03.858,734] <dbg> bt_att: bt_att_recv: Received ATT chan 0x85a0884 code 0x09 len 120
d_00: @00:00:03.858744  (CPU:0): [00:00:03.858,734] <dbg> bt_att: att_handle_read_type_rsp: 
d_00: @00:00:03.858744  (CPU:0): [00:00:03.858,734] <dbg> bt_att: att_handle_rsp: chan 0x85a0884 err 0 len 120: 070200200300052a05000a0600292b07000208002a2b0a00020b00002a0c00020d00012a0e00020f00042a1100041200062a1400121500c92b17001a1800ca2b
d_00: @00:00:03.858744  (CPU:0): [00:00:03.858,734] <dbg> bt_att: bt_att_req_free: req 0x85a06e0

The problem here is that we only send a request to one device, and the log does not show any other activity (for several) seconds on conn 0x84f48b0 (which is the one that appears faulty)

[Thalley]

Enabling CONFIG_BT_HCI_CORE_LOG_LEVEL_DBG=y shows that we are in fact receiving 2 ACL packages from the controller with the same content; one for handle 1 (unexpected) and one for handle 0 (expected).

d_00: @00:00:03.788288  (CPU:0): [00:00:03.788,269] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x859cd90 len 7
d_00: @00:00:03.788288  (CPU:0): [00:00:03.788,269] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
d_00: @00:00:03.788288  (CPU:0): [00:00:03.788,269] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
d_00: @00:00:03.788288  (CPU:0): [00:00:03.788,269] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
d_00: @00:00:03.788288  (CPU:0): [00:00:03.788,269] <dbg> bt_hci_core: tx_processor: TX process start
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x859cfe0 len 129
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: rx_work_handler: buf 0x859cfe0 type 8 len 129
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: hci_acl: buf 0x859cfe0
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: hci_acl: handle 1 len 125 flags 2
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 121 conn 0x84f48b0
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x85a09c0 len 121
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_att: bt_att_recv: Received ATT chan 0x85a09bc code 0x09 len 120
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_att: att_handle_read_type_rsp: 
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_att: att_handle_rsp: chan 0x85a09bc err 0 len 120: 070200200300052a05000a0600292b07000208002a2b0a00020b00002a0c00020d00012a0e00020f00042a1100041200062a1400121500c92b17001a1800ca2b
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <wrn> bt_att: att_handle_rsp: No pending ATT request
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_att: att_disconnect: ATT disconnecting device D5:90:2D:9B:9A:EC (random)
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_att: bt_att_disconnected: chan 0x85a09c0 cid 0x0004
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_att: att_chan_detach: chan 0x85a09bc
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x0406 param_len 3
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x859f21c
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x859f21c opcode 0x0406 len 6
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: tx_processor: TX process start
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: hci_core_send_cmd: fetch cmd
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: hci_core_send_cmd: Sending command 0x0406 (buf 0x859f21c) to driver
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: bt_send: buf 0x859f21c len 6 type 1
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: tx_processor: TX process start
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x859cd90 len 6
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: hci_cmd_status: opcode 0x0406
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: hci_cmd_done: opcode 0x0406 status 0x00  buf 0x859cd90
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: hci_cmd_done: sync cmd released
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x859f21c opcode 0x0406 len 0
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: bt_send_one_host_num_completed_packets: Reporting completed packet for handle 1
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x0c35 param_len 5
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x859f21c
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: bt_send: buf 0x859f21c len 8 type 1
d_00: @00:00:03.789936  (CPU:0): [00:00:03.789,916] <dbg> bt_hci_core: tx_processor: TX process start
d_00: @00:00:03.858744  (CPU:0): [00:00:03.858,734] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x859cfe0 len 129
d_00: @00:00:03.858744  (CPU:0): [00:00:03.858,734] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
d_00: @00:00:03.858744  (CPU:0): [00:00:03.858,734] <dbg> bt_hci_core: rx_work_handler: buf 0x859cfe0 type 8 len 129
d_00: @00:00:03.858744  (CPU:0): [00:00:03.858,734] <dbg> bt_hci_core: hci_acl: buf 0x859cfe0
d_00: @00:00:03.858744  (CPU:0): [00:00:03.858,734] <dbg> bt_hci_core: hci_acl: handle 0 len 125 flags 2
d_00: @00:00:03.858744  (CPU:0): [00:00:03.858,734] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 121 conn 0x84f47c0
d_00: @00:00:03.858744  (CPU:0): [00:00:03.858,734] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x85a0888 len 121
d_00: @00:00:03.858744  (CPU:0): [00:00:03.858,734] <dbg> bt_att: bt_att_recv: Received ATT chan 0x85a0884 code 0x09 len 120
d_00: @00:00:03.858744  (CPU:0): [00:00:03.858,734] <dbg> bt_att: att_handle_read_type_rsp: 
d_00: @00:00:03.858744  (CPU:0): [00:00:03.858,734] <dbg> bt_att: att_handle_rsp: chan 0x85a0884 err 0 len 120: 070200200300052a05000a0600292b07000208002a2b0a00020b00002a0c00020d00012a0e00020f00042a1100041200062a1400121500c92b17001a1800ca2b
d_00: @00:00:03.858744  (CPU:0): [00:00:03.858,734] <dbg> bt_att: bt_att_req_free: req 0x85a06e0