tests/bsim/bluetooth/audio/test_scripts/cap_broadcast_ac_12.sh failing in main

[aescolar]

Describe the bug
One BT audio CAP Broadcast AC test is failing in main:
tests/bsim/bluetooth/audio/test_scripts/cap_broadcast_ac_12.sh
in its "Execute_AC_12 48_4_1" step

To Reproduce
Make sure you have bsim installed and are ready to build targeting the nrf52_bsim

1. tests/bsim/bluetooth/audio/compile.sh
2. tests/bsim/bluetooth/audio/test_scripts/cap_broadcast_ac_12.sh

Expected behavior
No test failures

Impact
Failures in CI, blocking PRs

Logs and console output

...
d_00: @00:00:58.014617  [5800]: Stream 0x84d4240 sent with seq_num 5800
d_01: @00:00:58.077226  Received BASE with 1 subgroups from broadcast sink 0x854a3a0
d_01: @00:00:58.077226  Metadata updated
d_01: @00:00:58.077226  type 2 len 2
d_01: @00:00:58.617227  Received BASE with 1 subgroups from broadcast sink 0x854a3a0
d_01: @00:00:58.617227  Metadata updated
d_01: @00:00:58.617227  type 2 len 2
d_00: @00:00:59.014617  [5900]: Stream 0x84d4240 sent with seq_num 5900
d_01: @00:00:59.157227  Received BASE with 1 subgroups from broadcast sink 0x854a3a0
d_01: @00:00:59.157227  Metadata updated
d_01: @00:00:59.157227  type 2 len 2
d_01: @00:00:59.697227  Received BASE with 1 subgroups from broadcast sink 0x854a3a0
d_01: @00:00:59.697227  Metadata updated
d_01: @00:00:59.697227  type 2 len 2
d_00: @00:01:00.000722  TESTCASE NOT PASSED at exit (test return (1) indicates it was still in progress)
d_01: @00:01:00.008038  TESTCASE NOT PASSED at exit (test return (1) indicates it was still in progress)

Environment (please complete the following information):

• OS: Ubuntu 24.04
• Toolchain (e.g Zephyr SDK, ...): Host gcc 14
• Commit SHA or Version used: main after f970b06

Additional context
Failure started after #80228 got merged
f970b06

[Thalley]

Failures in CI, blocking PRs

Just to be clear: It's only blocking a few PRs :)

This issue is seen in a few PRs (#79931, #80691).
The issue is that the host stops receiving data from the controller.
It receives exactly 8 SDUs, which corresponds to the number of buffers configured for the test: CONFIG_BT_CTLR_ISO_RX_BUFFERS=8

The issue is timing related it seems, and modifying the number of octets sent or simply add a small k_sleep in the receiver "fixes" the issue.

I have only seen it happen on the nRF52 BSIM, and have not been able to reproduce with the nRF53 BSIM nor on target.

I believe it's an issue in the controller, but there is always a chance that the host is not free'ing the buffers, but from the logs I've seen there is no indication of any issues in the host:

d_01: @00:00:01.573910  [0]: Incoming audio on stream 0x84c6ea0 len 160 and ts 1567441
d_00: @00:00:01.573911  [00:00:01.573,883] <dbg> bt_iso: validate_send: chan 0x8535800 len 160
d_00: @00:00:01.573911  [00:00:01.573,883] <dbg> bt_iso: bt_iso_chan_send: chan 0x8535800 len 160
d_00: @00:00:01.573911  [00:00:01.573,883] <dbg> bt_iso: bt_iso_chan_send: send-iso (no ts)
d_00: @00:00:01.573911  [00:00:01.573,883] <dbg> bt_iso: conn_iso_send: 0x85a6540 put on list
d_00: @00:00:01.573911  [00:00:01.573,883] <dbg> bt_iso: iso_data_pull: conn 0x850db20 amount 255
d_00: @00:00:01.573911  [00:00:01.573,883] <dbg> bt_iso: iso_data_pull: last frag, pop buf
d_00: @00:00:01.573911  [00:00:01.573,883] <dbg> bt_iso: iso_data_pull: conn 0x850db20 amount 255
d_00: @00:00:01.573911  [00:00:01.573,883] <dbg> bt_iso: iso_data_pull: signaled ready but no frag available
d_01: @00:00:01.583910  [00:00:01.583,892] <dbg> bt_iso: hci_iso: buf 0x85aaea0
d_01: @00:00:01.583910  [00:00:01.583,892] <dbg> bt_iso: hci_iso: handle 5 len 168 flags 6
d_01: @00:00:01.583910  [00:00:01.583,892] <dbg> bt_iso: bt_iso_recv: handle 5 len 168 flags 0x06 pb 0x02 ts 0x01
d_01: @00:00:01.583910  [00:00:01.583,892] <dbg> bt_iso: bt_iso_recv: Single, len 160 total 160 flags 0x00 timestamp 1577441
d_00: @00:00:01.583911  [00:00:01.583,892] <dbg> bt_iso: validate_send: chan 0x8535800 len 160
d_00: @00:00:01.583911  [00:00:01.583,892] <dbg> bt_iso: bt_iso_chan_send: chan 0x8535800 len 160
d_00: @00:00:01.583911  [00:00:01.583,892] <dbg> bt_iso: bt_iso_chan_send: send-iso (no ts)
d_00: @00:00:01.583911  [00:00:01.583,892] <dbg> bt_iso: conn_iso_send: 0x85a6540 put on list
d_00: @00:00:01.583911  [00:00:01.583,892] <dbg> bt_iso: iso_data_pull: conn 0x850db20 amount 255
d_00: @00:00:01.583911  [00:00:01.583,892] <dbg> bt_iso: iso_data_pull: last frag, pop buf
d_00: @00:00:01.583911  [00:00:01.583,892] <dbg> bt_iso: iso_data_pull: conn 0x850db20 amount 255
d_00: @00:00:01.583911  [00:00:01.583,892] <dbg> bt_iso: iso_data_pull: signaled ready but no frag available
d_01: @00:00:01.593910  [00:00:01.593,902] <dbg> bt_iso: hci_iso: buf 0x85aaea0
d_01: @00:00:01.593910  [00:00:01.593,902] <dbg> bt_iso: hci_iso: handle 5 len 168 flags 6
d_01: @00:00:01.593910  [00:00:01.593,902] <dbg> bt_iso: bt_iso_recv: handle 5 len 168 flags 0x06 pb 0x02 ts 0x01
d_01: @00:00:01.593910  [00:00:01.593,902] <dbg> bt_iso: bt_iso_recv: Single, len 160 total 160 flags 0x00 timestamp 1587441
d_00: @00:00:01.593911  [00:00:01.593,902] <dbg> bt_iso: validate_send: chan 0x8535800 len 160
d_00: @00:00:01.593911  [00:00:01.593,902] <dbg> bt_iso: bt_iso_chan_send: chan 0x8535800 len 160
d_00: @00:00:01.593911  [00:00:01.593,902] <dbg> bt_iso: bt_iso_chan_send: send-iso (no ts)
d_00: @00:00:01.593911  [00:00:01.593,902] <dbg> bt_iso: conn_iso_send: 0x85a6540 put on list
d_00: @00:00:01.593911  [00:00:01.593,902] <dbg> bt_iso: iso_data_pull: conn 0x850db20 amount 255
d_00: @00:00:01.593911  [00:00:01.593,902] <dbg> bt_iso: iso_data_pull: last frag, pop buf
d_00: @00:00:01.593911  [00:00:01.593,902] <dbg> bt_iso: iso_data_pull: conn 0x850db20 amount 255
d_00: @00:00:01.593911  [00:00:01.593,902] <dbg> bt_iso: iso_data_pull: signaled ready but no frag available
d_01: @00:00:01.603910  [00:00:01.603,881] <dbg> bt_iso: hci_iso: buf 0x85aaea0
d_01: @00:00:01.603910  [00:00:01.603,881] <dbg> bt_iso: hci_iso: handle 5 len 168 flags 6
d_01: @00:00:01.603910  [00:00:01.603,881] <dbg> bt_iso: bt_iso_recv: handle 5 len 168 flags 0x06 pb 0x02 ts 0x01
d_01: @00:00:01.603910  [00:00:01.603,881] <dbg> bt_iso: bt_iso_recv: Single, len 160 total 160 flags 0x00 timestamp 1597441
d_00: @00:00:01.603911  [00:00:01.603,881] <dbg> bt_iso: validate_send: chan 0x8535800 len 160
d_00: @00:00:01.603911  [00:00:01.603,881] <dbg> bt_iso: bt_iso_chan_send: chan 0x8535800 len 160
d_00: @00:00:01.603911  [00:00:01.603,881] <dbg> bt_iso: bt_iso_chan_send: send-iso (no ts)
d_00: @00:00:01.603911  [00:00:01.603,881] <dbg> bt_iso: conn_iso_send: 0x85a6540 put on list
d_00: @00:00:01.603911  [00:00:01.603,881] <dbg> bt_iso: iso_data_pull: conn 0x850db20 amount 255
d_00: @00:00:01.603911  [00:00:01.603,881] <dbg> bt_iso: iso_data_pull: last frag, pop buf
d_00: @00:00:01.603911  [00:00:01.603,881] <dbg> bt_iso: iso_data_pull: conn 0x850db20 amount 255
d_00: @00:00:01.603911  [00:00:01.603,881] <dbg> bt_iso: iso_data_pull: signaled ready but no frag available
d_01: @00:00:01.613910  [00:00:01.613,891] <dbg> bt_iso: hci_iso: buf 0x85aaea0
d_01: @00:00:01.613910  [00:00:01.613,891] <dbg> bt_iso: hci_iso: handle 5 len 168 flags 6
d_01: @00:00:01.613910  [00:00:01.613,891] <dbg> bt_iso: bt_iso_recv: handle 5 len 168 flags 0x06 pb 0x02 ts 0x01
d_01: @00:00:01.613910  [00:00:01.613,891] <dbg> bt_iso: bt_iso_recv: Single, len 160 total 160 flags 0x00 timestamp 1607441
d_00: @00:00:01.613911  [00:00:01.613,891] <dbg> bt_iso: validate_send: chan 0x8535800 len 160
d_00: @00:00:01.613911  [00:00:01.613,891] <dbg> bt_iso: bt_iso_chan_send: chan 0x8535800 len 160
d_00: @00:00:01.613911  [00:00:01.613,891] <dbg> bt_iso: bt_iso_chan_send: send-iso (no ts)
d_00: @00:00:01.613911  [00:00:01.613,891] <dbg> bt_iso: conn_iso_send: 0x85a6540 put on list
d_00: @00:00:01.613911  [00:00:01.613,891] <dbg> bt_iso: iso_data_pull: conn 0x850db20 amount 255
d_00: @00:00:01.613911  [00:00:01.613,891] <dbg> bt_iso: iso_data_pull: last frag, pop buf
d_00: @00:00:01.613911  [00:00:01.613,891] <dbg> bt_iso: iso_data_pull: conn 0x850db20 amount 255
d_00: @00:00:01.613911  [00:00:01.613,891] <dbg> bt_iso: iso_data_pull: signaled ready but no frag available
d_01: @00:00:01.623910  [00:00:01.623,901] <dbg> bt_iso: hci_iso: buf 0x85aaea0
d_01: @00:00:01.623910  [00:00:01.623,901] <dbg> bt_iso: hci_iso: handle 5 len 168 flags 6
d_01: @00:00:01.623910  [00:00:01.623,901] <dbg> bt_iso: bt_iso_recv: handle 5 len 168 flags 0x06 pb 0x02 ts 0x01
d_01: @00:00:01.623910  [00:00:01.623,901] <dbg> bt_iso: bt_iso_recv: Single, len 160 total 160 flags 0x00 timestamp 1617441
d_00: @00:00:01.623911  [00:00:01.623,901] <dbg> bt_iso: validate_send: chan 0x8535800 len 160
d_00: @00:00:01.623911  [00:00:01.623,901] <dbg> bt_iso: bt_iso_chan_send: chan 0x8535800 len 160
d_00: @00:00:01.623911  [00:00:01.623,901] <dbg> bt_iso: bt_iso_chan_send: send-iso (no ts)
d_00: @00:00:01.623911  [00:00:01.623,901] <dbg> bt_iso: conn_iso_send: 0x85a6540 put on list
d_00: @00:00:01.623911  [00:00:01.623,901] <dbg> bt_iso: iso_data_pull: conn 0x850db20 amount 255
d_00: @00:00:01.623911  [00:00:01.623,901] <dbg> bt_iso: iso_data_pull: last frag, pop buf
d_00: @00:00:01.623911  [00:00:01.623,901] <dbg> bt_iso: iso_data_pull: conn 0x850db20 amount 255
d_00: @00:00:01.623911  [00:00:01.623,901] <dbg> bt_iso: iso_data_pull: signaled ready but no frag available
d_01: @00:00:01.633910  [00:00:01.633,880] <dbg> bt_iso: hci_iso: buf 0x85aaea0
d_01: @00:00:01.633910  [00:00:01.633,880] <dbg> bt_iso: hci_iso: handle 5 len 168 flags 6
d_01: @00:00:01.633910  [00:00:01.633,880] <dbg> bt_iso: bt_iso_recv: handle 5 len 168 flags 0x06 pb 0x02 ts 0x01
d_01: @00:00:01.633910  [00:00:01.633,880] <dbg> bt_iso: bt_iso_recv: Single, len 160 total 160 flags 0x00 timestamp 1627441
d_00: @00:00:01.633911  [00:00:01.633,880] <dbg> bt_iso: validate_send: chan 0x8535800 len 160
d_00: @00:00:01.633911  [00:00:01.633,880] <dbg> bt_iso: bt_iso_chan_send: chan 0x8535800 len 160
d_00: @00:00:01.633911  [00:00:01.633,880] <dbg> bt_iso: bt_iso_chan_send: send-iso (no ts)
d_00: @00:00:01.633911  [00:00:01.633,880] <dbg> bt_iso: conn_iso_send: 0x85a6540 put on list
d_00: @00:00:01.633911  [00:00:01.633,880] <dbg> bt_iso: iso_data_pull: conn 0x850db20 amount 255
d_00: @00:00:01.633911  [00:00:01.633,880] <dbg> bt_iso: iso_data_pull: last frag, pop buf
d_00: @00:00:01.633911  [00:00:01.633,880] <dbg> bt_iso: iso_data_pull: conn 0x850db20 amount 255
d_00: @00:00:01.633911  [00:00:01.633,880] <dbg> bt_iso: iso_data_pull: signaled ready but no frag available
d_01: @00:00:01.643910  [00:00:01.643,890] <dbg> bt_iso: hci_iso: buf 0x85aaea0
d_01: @00:00:01.643910  [00:00:01.643,890] <dbg> bt_iso: hci_iso: handle 5 len 168 flags 6
d_01: @00:00:01.643910  [00:00:01.643,890] <dbg> bt_iso: bt_iso_recv: handle 5 len 168 flags 0x06 pb 0x02 ts 0x01
d_01: @00:00:01.643910  [00:00:01.643,890] <dbg> bt_iso: bt_iso_recv: Single, len 160 total 160 flags 0x00 timestamp 1637441
d_00: @00:00:01.643910  [00:00:01.643,890] <dbg> bt_iso: validate_send: chan 0x8535800 len 160
d_00: @00:00:01.643910  [00:00:01.643,890] <dbg> bt_iso: bt_iso_chan_send: chan 0x8535800 len 160
d_00: @00:00:01.643910  [00:00:01.643,890] <dbg> bt_iso: bt_iso_chan_send: send-iso (no ts)
d_00: @00:00:01.643910  [00:00:01.643,890] <dbg> bt_iso: conn_iso_send: 0x85a6540 put on list
d_00: @00:00:01.643910  [00:00:01.643,890] <dbg> bt_iso: iso_data_pull: conn 0x850db20 amount 255
d_00: @00:00:01.643910  [00:00:01.643,890] <dbg> bt_iso: iso_data_pull: last frag, pop buf
d_00: @00:00:01.643910  [00:00:01.643,890] <dbg> bt_iso: iso_data_pull: conn 0x850db20 amount 255
d_00: @00:00:01.643910  [00:00:01.643,890] <dbg> bt_iso: iso_data_pull: signaled ready but no frag available
d_00: @00:00:01.653911  [00:00:01.653,900] <dbg> bt_iso: validate_send: chan 0x8535800 len 160
d_00: @00:00:01.653911  [00:00:01.653,900] <dbg> bt_iso: bt_iso_chan_send: chan 0x8535800 len 160
d_00: @00:00:01.653911  [00:00:01.653,900] <dbg> bt_iso: bt_iso_chan_send: send-iso (no ts)

It is (almost) without a doubt an issue on the ISO sync receiver.