Bluetooth: Controller: Missing CIS Established event with default ACL buffer size

[Thalley]

Describe the bug
If CONFIG_BT_BUF_ACL_RX_SIZE/CONFIG_BT_CTLR_DATA_LENGTH_MAX is set to their default value of 27 then it seems that there's an issue with generating/providing the CIS Established event to the host.

To Reproduce
Steps to reproduce the behavior:

1. Comment out CONFIG_BT_BUF_ACL_RX_SIZE and CONFIG_BT_CTLR_DATA_LENGTH_MAX in https://github.com/zephyrproject-rtos/zephyr/blob/main/samples/bluetooth/hci_ipc/nrf5340_cpunet_iso-bt_ll_sw_split.conf
2. west build -b nrf5340_audio_dk/nrf5340/cpuapp --sysbuild samples/bluetooth/bap_unicast_client/ -- -DCONFIG_BT_ISO_LOG_LEVEL_DBG=y
3. west flash
4. west build -b nrf5340_audio_dk/nrf5340/cpuapp --sysbuild samples/bluetooth/bap_unicast_server/ -- -DCONFIG_BT_ISO_LOG_LEVEL_DBG=y
5. west flash
6. See unicast client having a CIS stuck in the connecting state

Expected behavior
Expect that the ACL buffer size does not affect the generation of the CIS established event / CIS establishment.

Impact
A workaround is simply setting the value higher. At the time of reporting this, a minimum required value has not been determined, but at least setting 255/251 (the values configured by https://github.com/zephyrproject-rtos/zephyr/blob/main/samples/bluetooth/hci_ipc/nrf5340_cpunet_iso-bt_ll_sw_split.conf works).

Logs and console output

Connecting streams
[00:00:09.021,728] <dbg> bt_iso: bt_iso_chan_set_state_debug: chan 0x200078b4 iso 0x20006640 disconnected -> connecting
[00:00:09.372,314] <dbg> bt_iso: hci_le_cis_established: status 0x00  handle 7
[00:00:09.372,344] <dbg> bt_iso: store_cis_info: iso_chan 0x200078b4 tx 0x200078f8 rx 0x200078d8
[00:00:09.372,344] <dbg> bt_iso: bt_iso_connected: 0x20006640
[00:00:09.372,406] <dbg> bt_iso: bt_iso_chan_set_state_debug: chan 0x200078b4 iso 0x20006640 connecting -> connected
Audio Stream 0x20007478 connected
Audio Stream 0x20007428 connected
[00:00:09.372,985] <dbg> bt_iso: bt_iso_chan_set_state_debug: chan 0x20007914 iso 0x20006738 disconnected -> **connecting**
Audio Stream 0x20007428 started

Environment (please complete the following information):

• Toolchain (e.g Zephyr SDK, ...): Zephyr SDK
• Commit SHA or Version used: f7a2b4e

Additional context
The issue was found during some PTS testing, and a fix was done in #89680 for the BT Tester. In those cases connecting a single CIS fails, but in the samples we properly connect the first CIS, but not the second. This could indicate that only the last (or only if there's only a single CIS) fails to be established.

[Thalley]

Possibly related issue: #59173
Possibly related PR: #89258

[cvinayak]

Diff:

diff --git a/samples/bluetooth/bap_unicast_client/prj.conf b/samples/bluetooth/bap_unicast_client/prj.conf
index 6d6658d728b..f1d8fadc77f 100644
--- a/samples/bluetooth/bap_unicast_client/prj.conf
+++ b/samples/bluetooth/bap_unicast_client/prj.conf
@@ -17,3 +17,5 @@ CONFIG_BT_BAP_UNICAST_CLIENT_ASE_SRC_COUNT=2
 CONFIG_BT_KEYS_OVERWRITE_OLDEST=y
 
 CONFIG_BT_EXT_ADV=y
+
+CONFIG_BT_USE_DEBUG_KEYS=y
diff --git a/samples/bluetooth/bap_unicast_client/src/main.c b/samples/bluetooth/bap_unicast_client/src/main.c
index fdc0ed249ff..d7e5277e2e2 100644
--- a/samples/bluetooth/bap_unicast_client/src/main.c
+++ b/samples/bluetooth/bap_unicast_client/src/main.c
@@ -193,7 +193,7 @@ static void device_found(const bt_addr_le_t *addr, int8_t rssi, uint8_t type,
        printk("Device found: %s (RSSI %d)\n", addr_str, rssi);
 
        /* connect only to devices in close proximity */
-       if (rssi < -50) {
+       if (rssi < -60) {
                return;
        }
 

Build client:

$ west build -b nrf5340bsim/nrf5340/cpuapp --sysbuild ../../samples/bluetooth/bap_unicast_client -- -DCONFIG_BT_ISO_LOG_LEVEL_DBG=y

Build Server:

$ west build -b nrf5340bsim/nrf5340/cpuapp --sysbuild ../../samples/bluetooth/bap_unicast_server -- -DCONFIG_BT_ISO_LOG_LEVEL_DBG=y

Running (sh ~/test.sh > log.txt 2>&1) where test.sh is:

#! /bin/sh

./build/bap_unicast_client/zephyr/zephyr.exe -s=temp -RealEncryption=1 -d=0 &
../bap_unicast_server/build/bap_unicast_server/zephyr/zephyr.exe -s=temp -RealEncryption=1 -d=1

and (in tools/bsim/bin folder):

./bs_2G4_phy_v1 -s=temp -D=2 -sim_length=30e6

Logs (snippet):

d_00: @00:00:08.239712  (CPU:0): Enabling streams
d_01: @00:00:08.308005  (CPU:0): Enable: stream 0x8184ca0 meta_len 4
d_00: @00:00:08.378656  (CPU:0): Audio Stream 0x81997c0 enabled
d_01: @00:00:08.448005  (CPU:0): Enable: stream 0x8184cc4 meta_len 4
d_00: @00:00:08.518656  (CPU:0): Audio Stream 0x81997e8 enabled
d_01: @00:00:08.588006  (CPU:0): Enable: stream 0x8184d00 meta_len 4
d_00: @00:00:08.658655  (CPU:0): Audio Stream 0x8199810 enabled
d_00: @00:00:08.658655  (CPU:0): Streams enabled
d_00: @00:00:08.658655  (CPU:0): Connecting streams
d_00: @00:00:08.658655  (CPU:0): [00:00:08.658,630] �[0m<dbg> bt_iso: bt_iso_chan_set_state_debug: chan 0x819e0c0 iso 0x819dd00 disconnected -> connecting�[0m
d_01: @00:00:08.798090  (CPU:0): [00:00:08.798,065] �[0m<dbg> bt_iso: hci_le_cis_req: acl_handle 0 cis_handle 7 cig_id 0 cis 0�[0m
d_01: @00:00:08.798090  (CPU:0): [00:00:08.798,065] �[0m<dbg> bt_iso: iso_accept: 0x8188980�[0m
d_01: @00:00:08.798090  (CPU:0): [00:00:08.798,065] �[0m<dbg> bt_iso: bt_iso_chan_add: iso 0x8188980 chan 0x81890e0�[0m
d_01: @00:00:08.798090  (CPU:0): [00:00:08.798,065] �[0m<dbg> bt_iso: bt_iso_chan_set_state_debug: chan 0x81890e0 iso 0x8188980 disconnected -> connecting�[0m
d_01: @00:00:09.009709  (CPU:0): [00:00:09.009,704] �[0m<dbg> bt_iso: hci_le_cis_established: status 0x00  handle 7�[0m
d_01: @00:00:09.009709  (CPU:0): [00:00:09.009,704] �[0m<dbg> bt_iso: store_cis_info: iso_chan 0x81890e0 tx 0x8189124 rx 0x8189104�[0m
d_01: @00:00:09.009709  (CPU:0): [00:00:09.009,704] �[0m<dbg> bt_iso: bt_iso_connected: 0x8188980�[0m
d_01: @00:00:09.009709  (CPU:0): [00:00:09.009,704] �[0m<dbg> bt_iso: bt_iso_chan_set_state_debug: chan 0x81890e0 iso 0x8188980 connecting -> connected�[0m
d_01: @00:00:09.009709  (CPU:0): Audio Stream 0x8184ca0 started
d_00: @00:00:09.009903  (CPU:0): [00:00:09.009,887] �[0m<dbg> bt_iso: hci_le_cis_established: status 0x00  handle 7�[0m
d_00: @00:00:09.009903  (CPU:0): [00:00:09.009,887] �[0m<dbg> bt_iso: store_cis_info: iso_chan 0x819e0c0 tx 0x819e104 rx 0x819e0e4�[0m
d_00: @00:00:09.009903  (CPU:0): [00:00:09.009,887] �[0m<dbg> bt_iso: bt_iso_connected: 0x819dd00�[0m
d_00: @00:00:09.009903  (CPU:0): [00:00:09.009,887] �[0m<dbg> bt_iso: bt_iso_chan_set_state_debug: chan 0x819e0c0 iso 0x819dd00 connecting -> connected�[0m
d_00: @00:00:09.009903  (CPU:0): Audio Stream 0x8199810 connected
d_00: @00:00:09.009903  (CPU:0): Audio Stream 0x81997c0 connected
d_00: @00:00:09.009903  (CPU:0): [00:00:09.009,887] �[0m<dbg> bt_iso: bt_iso_chan_set_state_debug: chan 0x819e120 iso 0x819ddec disconnected -> connecting�[0m
d_00: @00:00:09.078203  (CPU:0): Audio Stream 0x81997c0 started
d_00: @00:00:09.078203  (CPU:0): [00:00:09.078,186] �[0m<inf> lc3: Extracting LC3 configuration values�[0m
d_00: @00:00:09.078203  (CPU:0): [00:00:09.078,186] �[0m<inf> lc3: Initializing sine wave data�[0m
d_00: @00:00:09.078203  (CPU:0): [00:00:09.078,186] �[0m<inf> lc3: Setting up LC3 encoder�[0m
d_00: @00:00:09.078203  (CPU:0): [00:00:09.078,186] �[0m<inf> stream_tx: Registered 0x81997c0 for TX�[0m
d_01: @00:00:09.099885  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.109884  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.119885  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.129885  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.139884  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.148090  (CPU:0): [00:00:09.148,071] �[0m<dbg> bt_iso: hci_le_cis_req: acl_handle 0 cis_handle 8 cig_id 0 cis 1�[0m
d_01: @00:00:09.148090  (CPU:0): [00:00:09.148,071] �[0m<dbg> bt_iso: iso_accept: 0x8188a6c�[0m
d_01: @00:00:09.148090  (CPU:0): [00:00:09.148,071] �[0m<dbg> bt_iso: bt_iso_chan_add: iso 0x8188a6c chan 0x8189140�[0m
d_01: @00:00:09.148090  (CPU:0): [00:00:09.148,071] �[0m<dbg> bt_iso: bt_iso_chan_set_state_debug: chan 0x8189140 iso 0x8188a6c disconnected -> connecting�[0m
d_01: @00:00:09.149885  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.159884  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.169884  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.179884  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.189884  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.199885  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.209884  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.219885  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.229885  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.239884  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.249885  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.259885  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.269885  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.279885  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.289884  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.299885  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.309884  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.319884  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.329884  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.339884  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.349885  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.359884  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.361929  (CPU:0): [00:00:09.361,907] �[0m<dbg> bt_iso: hci_le_cis_established: status 0x00  handle 8�[0m
d_01: @00:00:09.361929  (CPU:0): [00:00:09.361,907] �[0m<dbg> bt_iso: store_cis_info: iso_chan 0x8189140 tx 0x8189184 rx 0x8189164�[0m
d_01: @00:00:09.361929  (CPU:0): [00:00:09.361,907] �[0m<dbg> bt_iso: bt_iso_connected: 0x8188a6c�[0m
d_01: @00:00:09.361929  (CPU:0): [00:00:09.361,907] �[0m<dbg> bt_iso: bt_iso_chan_set_state_debug: chan 0x8189140 iso 0x8188a6c connecting -> connected�[0m
d_01: @00:00:09.361929  (CPU:0): Audio Stream 0x8184cc4 started
d_00: @00:00:09.362123  (CPU:0): [00:00:09.362,121] �[0m<dbg> bt_iso: hci_le_cis_established: status 0x00  handle 8�[0m
d_00: @00:00:09.362123  (CPU:0): [00:00:09.362,121] �[0m<dbg> bt_iso: store_cis_info: iso_chan 0x819e120 tx 0x819e164 rx 0x819e144�[0m
d_00: @00:00:09.362123  (CPU:0): [00:00:09.362,121] �[0m<dbg> bt_iso: bt_iso_connected: 0x819ddec�[0m
d_00: @00:00:09.362123  (CPU:0): [00:00:09.362,121] �[0m<dbg> bt_iso: bt_iso_chan_set_state_debug: chan 0x819e120 iso 0x819ddec connecting -> connected�[0m
d_00: @00:00:09.362123  (CPU:0): Audio Stream 0x81997e8 connected
d_00: @00:00:09.362123  (CPU:0): Streams connected
d_00: @00:00:09.362123  (CPU:0): Starting streams
d_01: @00:00:09.369885  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.379885  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.389884  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.399885  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.409884  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.419884  (CPU:0): RX stream 0x8184ca0 len 0
d_00: @00:00:09.428203  (CPU:0): Audio Stream 0x81997e8 started
d_00: @00:00:09.428203  (CPU:0): [00:00:09.428,192] �[0m<inf> lc3: Extracting LC3 configuration values�[0m
d_00: @00:00:09.428203  (CPU:0): [00:00:09.428,192] �[0m<inf> lc3: Initializing sine wave data�[0m
d_00: @00:00:09.428203  (CPU:0): [00:00:09.428,192] �[0m<inf> lc3: Setting up LC3 encoder�[0m
d_00: @00:00:09.428203  (CPU:0): [00:00:09.428,192] �[0m<inf> stream_tx: Registered 0x81997e8 for TX�[0m
d_01: @00:00:09.429884  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.439884  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.449885  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.459884  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.469885  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.479885  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.489884  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.492105  (CPU:0): RX stream 0x8184cc4 len 0
d_01: @00:00:09.497986  (CPU:0): Start: stream 0x8184d00
d_01: @00:00:09.497986  (CPU:0): Failed to send audio data on streams[0] (0x8184d00): (-74)
d_01: @00:00:09.497986  (CPU:0): Audio Stream 0x8184d00 started
d_01: @00:00:09.499885  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.502106  (CPU:0): RX stream 0x8184cc4 len 0
d_01: @00:00:09.508027  (CPU:0): Sending mock data with len 2 on streams[0] (0x8184d00)
d_01: @00:00:09.509885  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.512106  (CPU:0): RX stream 0x8184cc4 len 0
d_01: @00:00:09.518067  (CPU:0): Sending mock data with len 3 on streams[0] (0x8184d00)
d_01: @00:00:09.519885  (CPU:0): RX stream 0x8184ca0 len 0
d_01: @00:00:09.522106  (CPU:0): RX stream 0x8184cc4 len 0

@Thalley from the bsim output of the samples, both client and server have each received hci_le_cis_established as per the logs. I am I missing something (other than the logs having len 0 for Rx stream) ?. Nevermind, i did not use 27 byte ACL Tx/Rx PDU sizes...

[cvinayak]

I am seeing bus/usage/mem fault in the hci_ipc on the nrf5340 audio dk net core running the said samples on the PR: #89845

Screenshot on attaching to already hung device:

Screenshot on attaching to running device that throws bus fault: