nrf5340 audio DK running auracast.py transmit error

[chelalv]

I have a problem with the nrf52840dongle, it does not support BIS encryption. https://docs.nordicsemi.com/bundle/ncs-latest/page/nrfxlib/softdevice_controller/README.html
I switched to nrf5340 audio DK, which supports encryption
BUMBLE_LOGLEVEL=DEBUG python auracast.py transmit --input file:audioclub.wav --input-format auto --broadcast-name bumble --broadcast-code 0x12345678 serial:/dev/ttyACM1,1000000
DEBUG:bumble.host:### HOST -> CONTROLLER: HCI_LE_CREATE_BIG_COMMAND:
big_handle: 0
advertising_handle: 0
num_bis: 2
sdu_interval: 10000
max_sdu: 100
max_transport_latency: 65
rtn: 4
phy: PhyBit.LE_2M
packing: 0
framing: 0
encryption: 1
broadcast_code: 31323334350000000000000000000000
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_COMMAND_STATUS_EVENT:
status: PENDING
num_hci_command_packets: 1
command_opcode: HCI_LE_CREATE_BIG_COMMAND
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_LE_CREATE_BIG_COMPLETE_EVENT:
status: HCI_SUCCESS
big_handle: 0
big_sync_delay: 5950
transport_latency_big: 35950
phy: 2
nse: 5
bn: 1
pto: 1
irc: 2
max_pdu: 100
iso_interval: 8
connection_handle[0]: 6
connection_handle[1]: 5

But there is another problem,
DEBUG:bumble.host:### CONTROLLER -> HOST: HCI_COMMAND_STATUS_EVENT:
status: HCI_UNKNOWN_HCI_COMMAND_ERROR
num_hci_command_packets: 1
command_opcode: [OGF=0x19, OCF=0x0000]
WARNING:bumble.host:!!! no pending response future to set
I see that both HCI_LE_SETUP_ISO_DATA_PATH_COMMAND above have returned HCI_SUCCESS, so why do I get the error HCI_UNKNOWN_HCI_COMMAND_ERROR?
The following is the complete log：

audiodk-HCI_UNKNOWN_HCI_COMMAND_ERROR.txt

[chelalv]

The following is the controller information：

controller_info.txt

[barbibulle]

From the log, it seems that what happened is that the controller has received an HCI command with OGF=0x19 and OCF=0x0000 (not a valid HCI command), so it returns an event with status == HCI_UNKNOWN_HCI_COMMAND_ERROR. Since the Bumble stack would never send an HCI command with OFG=0x19, it means that somehow the HCI data between the host and the controller got corrupted. My best guess at this time is that the UART connection isn't reliable, possibly due to the lack of flow control, or some other issue. I will experiment with an nrf5340 board to see if I can reproduce this and figure out a solution (I did get LE Audio to work with an nrf5340 in the past, but I haven't tested it much, so that might explain why I have not run into this issue myself)

[barbibulle]

I was able to reproduce this issue. It looks like the Zephyr stack (not sure specifically what part of the stack is responsible, it may also be a problem with the Nordic SoftDevice implementation) doesn't properly manage buffers for ISO packets.
Here's what I see:
the sender (in this case the Bumble stack, with ISO data fed from the auracast.py app) sends ISO packets at a pretty fast rate. The sender paces itself based on the ISO buffer size and count reported by the controller (with my config, that ends up being: iso_data_packet_length=318,total_num_iso_data_packets=3, so 3 packets of up to 318 bytes. When the sender has 3 outstanding packets, it stops sending. When the controller sends back HCI_NUMBER_OF_COMPLETED_PACKETS_EVENT events with some number of completed packets (num_completed_packets), the Bumble stack can then send more packets, if some are ready. This serves as the ISO packet flow control (a similar logic is used for command packets).
The problem here is that depending on timing (which may be affects by logging, or even whether or not encryption is enabled or not), the Zephyr stack gets into a situation where a packet is received from the serial port, the hci_uart app tries to allocate a BT packet for it (buf = bt_buf_get_tx(bt_buf_type_from_h4(type, BT_BUF_OUT), K_NO_WAIT, NULL, 0); in main.c), which sometimes fails. At that point, the H4 parser state is reset, but that's pretty bad, because the next bytes received are going to be the reset of the ISO packets (whatever comes after the type byte at the start of the packet), so tons of errors will be encountered (trying to parse the rest of the payload of the ISO packet as new HCI packets), and it won't recover from that (by chance, some bytes in the rest of the ISO packet payload will look like an HCI command header, but that's bogus, and when that bogus packet is sent to the controller, it will respond with HCI_UNKNOWN_HCI_COMMAND_ERROR).

So, to summarize:
1/ The Zephyr/SoftDevice stack doesn't properly report the number of available buffers, so it is possible that an ISO packet will be sent when in fact there's no space available, causing bt_buf_get_tx to return an error.
2/ When that error happens, instead of cleanly discarding the packet entirely (its header and payload), only the header is discarded, and the H4 parser will attempt to parse the rest of the payload as valid HCI packets, which will eventually produce invalid HCI commands.

The best would be to fix issue 1 first, so that issue 2 isn't triggered. But, if somehow that's not possible for that reason, it may still be possible to recover from the error by either: 1/ find a way to re-queue the packet and retry later (when there will possibly be a buffer available), but that's a pretty complex logic, probably not worth the effort or 2/ cleanly discard the ENTIRE packet, so that the next received bytes will start at the next HCI packet header (this will drop the ISO packet, which the received should be able to recover from ideally, even if maybe not so gracefully, since the receiver will not know that this packet drop has occurred).

[barbibulle]

I looked into this a bit more, and found that, unfortunately, there's no direct relation between the HCI buffers used to send HCI packets to the controller and the number of buffers the controller actually has for itself. So there's no fool-proof way to guarantee you won't run out of buffers when sending HCI packets.
However, there seems to be a simple working solution, even if a bit sub-optimal: increase the number of TX buffers, so that there's less of a risk to run out before the packets are consumed.
I tried with CONFIG_BT_ISO_TX_BUF_COUNT=4 in my build config, and that seems to fix the issue.

NOTE: I'm also going to push a PR to allow setting a post-open delay for the serial port, as it looks like with the auto-detection of HW flow control on the Nordic UART, it can sometimes get stuck if we send data too soon after opening the port.

[chelalv]

I don't know how you compiled the nrf5340 code. I added sysbuild/ipc_radio/prj.conf as suggested by the Nordic engineer,
This conf is https://github.com/nrfconnect/sdk-nrf/blob/v3.0.2/applications/nrf5340_audio/sysbuild/ipc_radio/prj.conf,
This will compile a netcore image: ipc_radio.
I added CONFIG_BT_ISO_TX_BUF_COUNT=10 to sysbuild/ipc_radio/prj.conf, but the same error occurred. I changed it to 4, but it was still wrong. I also added it to the prj.conf in the project root directory, but the same error occurred.