Bluetooth: Controller: Data incoming on terminated PA and BIS handles

[Thalley]

Describe the bug
In babblesim (on both nrf52 and nrf5340) we have seen cases where there are either

• BIS data incoming on a BIS that the controller has already sent a BIG Sync terminated event for
• Periodic advertising reports on a PA Sync that has been terminated (BT_HCI_OP_LE_PER_ADV_TERMINATE_SYNC has been sent and a command complete has been sent to the host)

This has only been seen in babblesim, and only with the BT Tester BSIM tests.

To Reproduce
Steps to reproduce the behavior for nrf5340:

1. Checkout tests: Bluetooth: Tester: BAP BSIM test #87207
2. export BOARD=nrf5340bsim/nrf5340/cpuapp
3. zephyr/tests/bsim/bluetooth/tester/compile.sh
4. zephyr/tests/bsim/bluetooth/tester/tests_scripts/bap_broadcast.sh

See error

d_01: @00:00:01.601563  (CPU:0): [00:00:01.601,562] <dbg> bttester_bap_broadcast: stream_stopped: Stopped stream 0x846072c with reason 0x16
d_01: @00:00:01.601563  (CPU:0): [00:00:01.601,562] <dbg> bttester_bap_broadcast: recv_state_updated_cb: Receive state with ID 0 updated
d_01: @00:00:01.662078  (CPU:0): [00:00:01.662,048] <dbg> bttester_bap_broadcast: base_recv_cb: bis_index_bitfield 0x00000001
d_01: @00:00:01.662078  (CPU:0): [00:00:01.662,048] <dbg> bttester: tester_event: service 0x0e opcode 0x89
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <dbg> bttester_bap_broadcast: syncable_cb: Broadcaster PA found, encrypted 0, requested_bis_sync 0
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84c4b20 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84c4b20 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84c4b20 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84c4b20 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84c4b20 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84c4b20 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84c4b20 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84c4b20 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84c4b20 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84c4b20 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84c4b20 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84c4b20 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84c4b20 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84c4b20 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84c4b20 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <dbg> bttester_bap_broadcast: base_recv_cb: 
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <dbg> bttester_bap_broadcast: base_recv_cb: Received BASE: broadcast sink 0x84cee80 subgroups 1
d_11: @00:00:01.671631  [00:00:01.671,630] <dbg> bsim_btp: is_valid_packet_len: evt
d_11: @00:00:01.671631                                     0e 85 00 25 00 01 3a 04  3a 41 13 de 56 34 12 40 |...%..:. :A..V4.@
d_11: @00:00:01.671631                                     9c 00 00 01 06 00 00 00  00 10 02 01 03 02 02 01 |........ ........
d_11: @00:00:01.671631                                     05 03 01 00 00 00 03 04  28 00                   |........ (.      
d_01: @00:00:01.742215  (CPU:0): [00:00:01.742,187] <dbg> bttester: tester_event: service 0x0e opcode 0x85
d_01: @00:00:01.742404  (CPU:0): [00:00:01.742,401] <dbg> bttester_gap: pa_sync_terminated_cb: 
d_01: @00:00:01.742404  (CPU:0): [00:00:01.742,401] <dbg> bttester_gap: pa_sync_terminated_cb: PA sync lost with reason 22
d_01: @00:00:01.742404  (CPU:0): [00:00:01.742,401] <dbg> bttester: tester_event: service 0x01 opcode 0x8e
d_11: @00:00:01.751709  [00:00:01.751,708] <dbg> bsim_btp: is_valid_packet_len: evt
d_11: @00:00:01.751709                                     0e 89 00 1b 00 00 00 00  00 00 00 00 00 01 3a 04 |........ ......:.
d_11: @00:00:01.751709                                     3a 41 13 de 00 56 34 12  02 00 01 00 00 00 00 00 |:A...V4. ........
d_01: @00:00:01.852509  (CPU:0): [00:00:01.852,508] <dbg> bttester_bap_broadcast: base_recv_cb: bis_index_bitfield 0x00000001
d_01: @00:00:01.852878  (CPU:0): [00:00:01.852,874] <err> bt_scan: bt_hci_le_biginfo_adv_report: Unknown handle 0x0000 for periodic advertising report
d_01: @00:00:01.852878  (CPU:0): [00:00:01.852,874] <err> bt_iso: hci_iso: Unable to find conn for handle 7
d_01: @00:00:01.852878  (CPU:0): [00:00:01.852,874] <err> bt_iso: hci_iso: Unable to find conn for handle 7
d_01: @00:00:01.852878  (CPU:0): [00:00:01.852,874] <err> bt_iso: hci_iso: Unable to find conn for handle 7
d_01: @00:00:01.852878  (CPU:0): [00:00:01.852,874] <err> bt_iso: hci_iso: Unable to find conn for handle 7
d_01: @00:00:01.852878  (CPU:0): [00:00:01.852,874] <err> bt_iso: hci_iso: Unable to find conn for handle 7
d_01: @00:00:01.852878  (CPU:0): [00:00:01.852,874] <err> bt_iso: hci_iso: Unable to find conn for handle 7
d_01: @00:00:01.852878  (CPU:0): [00:00:01.852,874] <err> bt_scan: bt_hci_le_per_adv_report_common: Unknown handle 0x0000 for periodic advertising report
d_01: @00:00:01.852878  (CPU:0): [00:00:01.852,874] <err> bt_scan: bt_hci_le_biginfo_adv_report: Unknown handle 0x0000 for periodic advertising report

Steps to reproduce the behavior for nrf52

1. Checkout tests: Bluetooth: Tester: BAP BSIM test #87207
2. export BOARD=nrf52_bsim/native
3. zephyr/tests/bsim/bluetooth/tester/compile.sh
4. zephyr/tests/bsim/bluetooth/tester/tests_scripts/bap_broadcast.sh

d_01: @00:00:01.742404  [00:00:01.742,401] <dbg> bttester_gap: pa_sync_terminated_cb: 
d_01: @00:00:01.742404  [00:00:01.742,401] <dbg> bttester_gap: pa_sync_terminated_cb: PA sync lost with reason 22
d_01: @00:00:01.742404  [00:00:01.742,401] <dbg> bttester: tester_event: service 0x01 opcode 0x8e
d_11: @00:00:01.751709  [00:00:01.751,708] <dbg> bsim_btp: is_valid_packet_len: evt
d_11: @00:00:01.751709                                     0e 89 00 1b 00 00 00 00  00 00 00 00 00 01 04 3a |........ .......:
d_11: @00:00:01.751709                                     41 13 de fe 00 56 34 12  02 00 01 00 00 00 00 00 |A....V4. ........
d_01: @00:00:01.852509  [00:00:01.852,508] <dbg> bttester_bap_broadcast: base_recv_cb: bis_index_bitfield 0x00000001
d_01: @00:00:01.852878  [00:00:01.852,874] <err> bt_scan: bt_hci_le_biginfo_adv_report: Unknown handle 0x0000 for periodic advertising report
d_01: @00:00:01.852878  [00:00:01.852,874] <err> bt_iso: hci_iso: Unable to find conn for handle 7

Expected behavior
Expect to not receive any ISO data on a termianted BIG sync, nor any periodic advertising reports on a PA sync.

Impact
Since these are logged as errors by the host, this is a bad user/developer experience, but does not otherwise cause issues.

Logs and console output
See above

Environment (please complete the following information):

• OS: (e.g. Linux, MacOS, Windows): Arch Linux running Babblesim
• Toolchain (e.g Zephyr SDK, ...): Zephyr SDK
• Commit SHA or Version used: tests: Bluetooth: Tester: BAP BSIM test #87207 on top 6061deba555d148786ca2fd8193df7d6d6e1d0fcof

Additional context
There as a fix attempted by #87755 which did not solve this.
Similarly the change from #88279 does also not fix this issue.

[cvinayak]

Adding some printk in the Controller, it is seen that the Controller (CPU:1) does not send any ISO SDUs or Periodic Advertising/BIGInfo report after the HCI command to terminate the ISO Sync or PA terminate is handled. Is it possible that the Host is processing the received ISO SDUs and Reports after the command complete is processed by its Tx thread/Work?

d_01: @00:00:01.570629  (CPU:1): node_rx_recv: ISO Rx fifo put
d_01: @00:00:01.570629  (CPU:1): sink_sdu_emit_hci: ISO data->recv
d_01: @00:00:01.580630  (CPU:1): node_rx_recv: ISO Rx fifo put
d_01: @00:00:01.580630  (CPU:1): sink_sdu_emit_hci: ISO data->recv
d_01: @00:00:01.590629  (CPU:1): node_rx_recv: ISO Rx fifo put
d_01: @00:00:01.590629  (CPU:1): sink_sdu_emit_hci: ISO data->recv
d_01: @00:00:01.600630  (CPU:1): node_rx_recv: ISO Rx fifo put
d_01: @00:00:01.600630  (CPU:1): sink_sdu_emit_hci: ISO data->recv
d_01: @00:00:01.601563  (CPU:0): [00:00:01.601,562] <dbg> bttester: cmd_handler: cmd service 0x0e opcode 0x0f index 0x00
d_01: @00:00:01.601563  (CPU:0): [00:00:01.601,562] <dbg> bttester_bap_broadcast: btp_bap_broadcast_sink_stop: 
d_01: @00:00:01.601563  (CPU:1): cmd_handle: COMMAND COMPLETE/STATUS fifo put
d_01: @00:00:01.601563  (CPU:1): process_node: COMMAND COMPLETE/STATUS
d_01: @00:00:01.601563  (CPU:1): recv_thread: ACL/EVT data->recv
d_01: @00:00:01.601563  (CPU:0): [00:00:01.601,562] <dbg> bttester_bap_broadcast: stream_stopped: Stopped stream 0x846ae6c with reason 0x16
d_01: @00:00:01.601563  (CPU:0): [00:00:01.601,562] <dbg> bttester_bap_broadcast: recv_state_updated_cb: Receive state with ID 0 updated
d_01: @00:00:01.627717  (CPU:1): recv_thread: ACL/EVT data->recv
d_01: @00:00:01.627717  (CPU:1): recv_thread: ACL/EVT data->recv
d_01: @00:00:01.662078  (CPU:0): [00:00:01.662,048] <dbg> bttester_bap_broadcast: base_recv_cb: bis_index_bitfield 0x00000001
d_01: @00:00:01.662078  (CPU:0): [00:00:01.662,048] <dbg> bttester: tester_event: service 0x0e opcode 0x89
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <dbg> bttester_bap_broadcast: syncable_cb: Broadcaster PA found, encrypted 0, requested_bis_sync 0
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84cf6e0 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84cf6e0 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84cf6e0 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84cf6e0 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84cf6e0 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84cf6e0 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84cf6e0 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84cf6e0 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84cf6e0 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84cf6e0 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84cf6e0 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84cf6e0 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84cf6e0 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84cf6e0 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <err> bt_bap_broadcast_sink: broadcast_sink_iso_recv: iso 0x84cf6e0 not bound with ep
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <dbg> bttester_bap_broadcast: base_recv_cb: 
d_01: @00:00:01.662357  (CPU:0): [00:00:01.662,353] <dbg> bttester_bap_broadcast: base_recv_cb: Received BASE: broadcast sink 0x84d9a40 subgroups 1
d_11: @00:00:01.671631  [00:00:01.671,630] <dbg> bsim_btp: is_valid_packet_len: evt
d_11: @00:00:01.671631                                     0e 85 00 25 00 01 3a 04  3a 41 13 de 56 34 12 40 |...%..:. :A..V4.@
d_11: @00:00:01.671631                                     9c 00 00 01 06 00 00 00  00 10 02 01 03 02 02 01 |........ ........
d_11: @00:00:01.671631                                     05 03 01 00 00 00 03 04  28 00                   |........ (.      
d_01: @00:00:01.742215  (CPU:0): [00:00:01.742,187] <dbg> bttester: tester_event: service 0x0e opcode 0x85
d_01: @00:00:01.742404  (CPU:1): cmd_handle: COMMAND COMPLETE/STATUS fifo put
d_01: @00:00:01.742404  (CPU:1): process_node: COMMAND COMPLETE/STATUS
d_01: @00:00:01.742404  (CPU:1): recv_thread: ACL/EVT data->recv
d_01: @00:00:01.742404  (CPU:0): [00:00:01.742,401] <dbg> bttester_gap: pa_sync_terminated_cb: 
d_01: @00:00:01.742404  (CPU:0): [00:00:01.742,401] <dbg> bttester_gap: pa_sync_terminated_cb: PA sync lost with reason 22
d_01: @00:00:01.742404  (CPU:0): [00:00:01.742,401] <dbg> bttester: tester_event: service 0x01 opcode 0x8e
d_11: @00:00:01.751709  [00:00:01.751,708] <dbg> bsim_btp: is_valid_packet_len: evt
d_11: @00:00:01.751709                                     0e 89 00 1b 00 00 00 00  00 00 00 00 00 01 3a 04 |........ ......:.
d_11: @00:00:01.751709                                     3a 41 13 de 00 56 34 12  02 00 01 00 00 00 00 00 |:A...V4. ........
d_01: @00:00:01.852509  (CPU:0): [00:00:01.852,508] <dbg> bttester_bap_broadcast: base_recv_cb: bis_index_bitfield 0x00000001
d_01: @00:00:01.852878  (CPU:0): [00:00:01.852,874] <err> bt_scan: bt_hci_le_biginfo_adv_report: Unknown handle 0x0000 for periodic advertising report
d_01: @00:00:01.852878  (CPU:0): [00:00:01.852,874] <err> bt_iso: hci_iso: Unable to find conn for handle 7
d_01: @00:00:01.852878  (CPU:0): [00:00:01.852,874] <err> bt_iso: hci_iso: Unable to find conn for handle 7
d_01: @00:00:01.852878  (CPU:0): [00:00:01.852,874] <err> bt_iso: hci_iso: Unable to find conn for handle 7
d_01: @00:00:01.852878  (CPU:0): [00:00:01.852,874] <err> bt_iso: hci_iso: Unable to find conn for handle 7
d_01: @00:00:01.852878  (CPU:0): [00:00:01.852,874] <err> bt_iso: hci_iso: Unable to find conn for handle 7
d_01: @00:00:01.852878  (CPU:0): [00:00:01.852,874] <err> bt_iso: hci_iso: Unable to find conn for handle 7
d_01: @00:00:01.852878  (CPU:0): [00:00:01.852,874] <err> bt_scan: bt_hci_le_per_adv_report_common: Unknown handle 0x0000 for periodic advertising report
d_01: @00:00:01.852878  (CPU:0): [00:00:01.852,874] <err> bt_scan: bt_hci_le_biginfo_adv_report: Unknown handle 0x0000 for periodic advertising report

[Thalley]

bt_hci_recv calls bt_recv_unsafe which calls rx_queue_put which adds events to the bt_dev.rx_queue queue and then triggers the system workqueue that reads from it.

Not only does this delay the time from bt_hci_recv to the event being handled, it also changes which thread that handles it. This is fine, but clearly we are not going though bt_dev.rx_queue when there's a terminated sync or lost connection to remove all events for a specific periodic advertising sync or a BIG sync, a CIS or an ACL.

This issue seems to be in the host, and applies to all types of events, since events with BT_HCI_EVT_FLAG_RECV_PRIO is handled directly in bt_recv_unsafe, instead of being submitted to the workqueue.

@alwa-nordic @jhedberg how do we best deal with this? Getting errors in the log after a disconnection is not great for users. We have process_unack_tx for removing pending TX for a connection when it's disconnected, but I don't see anything for bt_dev.rx_queue.

[cvinayak]

Side note... correct me, currently the priority based handling of events is duplicated in both Host and Zephyr Controller when Host+Controller combined builds; i.e. use of BT_HCI_EVT_FLAG_RECV_PRIO (same named define in Host and Controller code base). When building Controller only, recently I have made the Controller to be single thread receive (eliminating prioritization of certain events). Refer to 47c7918. And as the Host still has the prioritization, which is essential to mitigate Tx thread deadlocks (waiting on num completed packet events that do not arrive) on disconnections/termination. May be, this duplication of the prioritization should only be in Host, even in the case of Host+Controller builds, right?

That said, yes, an investigation and a solution to flush bt_dev.rx_queue may be needed similar to flushing of pending Tx. Or, local/remote initiated disconnection/terminate will need a bottom-half implementation to "complete" and "call" callback after all Rx buffers are processed. I will vote for latter, to not flush Rx buffers when under race at the point of reception of disconnection/termination (say a Peripheral is connected to, Peripheral sends data and disconnects immediately, the Central shall not flush the received data handling disconnection event).

Ok wait... correct me again...

         case BT_HCI_EVT_DISCONN_COMPLETE:                                                           
                return BT_HCI_EVT_FLAG_RECV | BT_HCI_EVT_FLAG_RECV_PRIO;

The ACL disconnection may be handled as a top-half and bottom-half already... @Thalley this something we need to take inspiration for the BIS and PA terminate? The Command Complete needing top-half and bottom-half before generating the terminated callback?

[Thalley]

The ACL disconnection may be handled as a top-half and bottom-half already... @Thalley this something we need to take inspiration for the BIS and PA terminate? The Command Complete needing top-half and bottom-half before generating the terminated callback?

Good question. Semantically it makes sense to treat lost/terminated syncs in the same way we treat disconnects.

I'm having some trouble understanding how/why this works for ACLs though: It seems that a disconnect event will trigger a call to e.g. hci_disconn_complete_prio that then schedules deferred_work which will call notify_disconnected, but I don't see how all pending RX events are handled, i.e. there is no flushing of the bt_dev.rx_queue, so what's preventing the above issue from existing on ACLs? By the time notify_disconnected is called, couldn't there still be ACL RX events in the queue?

[cvinayak]

couldn't there still be ACL RX events in the queue?

hci_disconn_complete_prio() executes before hci_disconn_complete() to break any Tx deadlock, and latter executes in the rx_work_handler. As the Controller shall ensures that the BT_HCI_EVT_DISCONN_COMPLETE is generated after all ACL Rx packets, hence by the time hci_disconn_complete() executes sequential in the rx_work_handler() fetched from the bt_dev.rx_queue that will not be any more ACL Rx events thereafter.

notify_disconnected() is called after hci_disconn_complete() (when conn->state == BT_CONN_DISCONNECTED is set), not when conn->state == BT_CONN_DISCONNECT_COMPLETE which is set by hci_disconn_complete_prio()

[Thalley]

Thanks for the clarification.

For ISO/BIS and PA Syncs, the issue is that terminating these are synchronous functions, i.e. per_adv_sync_terminate and hci_le_big_sync_term will sends the HCI command and then await the BT_HCI_EVT_CMD_COMPLETE which is a BT_HCI_EVT_FLAG_RECV_PRIO and then that is handled before any pending RX. This is not the case for e.g. CIS and ACL, so it makes sense that we only see the issue for broadcast.

So we can either

1. Apply the procedure for ACL, and make the sync terminate functions async in the way that they will enter a "Disconnecting" state and then do a final cleanup once the non-prio event has been handled. The advantage of this is that, at least for BIS (not for PA), the behavior of bt_iso_big_terminate for source and receiver is the same, i.e. both are async and will have to await a callback. The downside of this, is that it's an API change, and that, unlike ACL/CIS, there is not a specific event we can await for (we only get a BT_HCI_EVT_CMD_COMPLETE), so we cannot in bt_hci_evt_get_flags apply a flag to make it similar to BT_HCI_EVT_DISCONN_COMPLETE without affecting all other uses of BT_HCI_EVT_CMD_COMPLETE.
2. On PA/BIS sync terminated, we can go through the bt_dev.rx_queue and process all events before returning
3. On receiving data on PA/BIS after termination, we do not log this as an error.

I also think that this issue exists for BT_HCI_EVT_LE_ADV_SET_TERMINATED, i.e. the host may have received this event while BT_HCI_OP_LE_REMOVE_ADV_SET is being handled, and similar to the above, this command only generates a BT_HCI_EVT_CMD_COMPLETE, although this is much less likely to happen.

I think option 1) makes the most sense in terms of being consistent with e.g. ACL/CIS, but the way that we handle this in Zephyr makes it quite tricky, as well as being an API change.
Option 2) could be an interesting approach, but I'm worried that we may end up with deadlocks somehow, as flushing the RX queue may trigger one or more application callbacks (although depending on thread priority, this would always be the case).
Option 3) is by far the simplest to implement