fix(ble_audio): Recover ISO HCI cmd from a dropped hciT wakeup

components/bt/esp_ble_iso/host/adapter/bluedroid/hci.c

@@ -80,6 +80,8 @@ static void direct_hci_complete_cb(BT_HDR *response, void *context)
 
     ARG_UNUSED(context);
 
+    LOG_INF("[B]DirectHciCompleteCb[%04x]", direct_hci_rsp.opcode);
+
     event_param_len = response->data[response->offset + 1];
 
     STREAM_TO_UINT16(opcode, stream);
@@ -115,6 +117,13 @@ static void direct_hci_complete_cb(BT_HDR *response, void *context)
     k_sem_give(&direct_hci_sem);
 }
 
+/* Dropped-wakeup recovery in send_sync below. SLICE is well above the ~5 ms
+ * round trip so a healthy command never kicks; the first kick already recovers,
+ * and the leftover budget is one final wait, keeping the total K_SEM_SHORT. */
+#define DIRECT_HCI_KICK_SLICE   (50 / portTICK_PERIOD_MS)
+#define DIRECT_HCI_KICK_MAX     3
+#define DIRECT_HCI_WAIT_REST    (K_SEM_SHORT - DIRECT_HCI_KICK_MAX * DIRECT_HCI_KICK_SLICE)
+
 tBTM_STATUS bt_le_bluedroid_hci_send_sync(uint16_t opcode,
                                           const uint8_t *cmd_params,
                                           uint8_t cmd_params_len,
@@ -123,6 +132,7 @@ tBTM_STATUS bt_le_bluedroid_hci_send_sync(uint16_t opcode,
 {
     BT_HDR *p;
     UINT8 *pp;
+    uint8_t kicks;
     hci_cmd_metadata_t *metadata;
 
     p = HCI_GET_CMD_BUF(cmd_params_len);
@@ -158,7 +168,50 @@ tBTM_STATUS bt_le_bluedroid_hci_send_sync(uint16_t opcode,
     hci_layer_get_interface()->transmit_command(p, direct_hci_complete_cb,
                                                 NULL, NULL);
 
-    if (k_sem_take(&direct_hci_sem, K_SEM_SHORT) != 0) {
+    for (kicks = 0; kicks < DIRECT_HCI_KICK_MAX; kicks++) {
+        if (k_sem_take_poll(&direct_hci_sem, DIRECT_HCI_KICK_SLICE) == 0) {
+            break;
+        }
+
+        LOG_WRN("[B]DirectHciKick[0x%04x][%u]", opcode, kicks + 1);
+
+        /* Re-post the downstream event: our own wakeup may have been dropped.
+         *
+         * transmit_command() does not write the command from this task. It
+         * appends to hci_host_env.command_queue and wakes the hciT worker via
+         * hci_downstream_data_post(), whose return value it discards.
+         * osi_thread_post_event() refuses to post while OSI_EVENT_FLAG_POSTING
+         * is set, and that flag is held by whichever task is mid-post from the
+         * moment it sets the flag until it is rescheduled: osi_thread_post()
+         * ends in osi_sem_give(work_sem), which immediately yields to the
+         * higher-priority hciT, so POSTING stays set across the whole handler
+         * run. A second producer landing in that window is rejected:
+         *
+         *   BTU      set QUEUED|POSTING; osi_thread_post() -> sem give --.
+         *   hciT     clear QUEUED; handler: send the ACL, command_queue  <-'
+         *            still empty -> break; block again
+         *   iso_task (same prio as BTU, round-robin) transmit_command():
+         *            enqueue cmd ok, post -> QUEUED clear but POSTING set
+         *            -> rejected, no wakeup, return value discarded
+         *   BTU      resumes, clears POSTING (too late)
+         *
+         * The command then sits in command_queue with nothing scheduled to
+         * drain it. It never reached commands_pending_response either, so
+         * Bluedroid's own COMMAND_PENDING_TIMEOUT never arms and only this
+         * task's sem timeout notices. That is expensive here: the caller is the
+         * ISO task, sole consumer of the ISO RX queue, so a full K_SEM_SHORT
+         * stall drops every SDU received during it.
+         *
+         * One slice later the POSTING holder has long been rescheduled, so this
+         * post lands and hciT drains the queued command. Bluedroid-only: NimBLE
+         * writes the command inline from the caller's task (ble_hs_hci_cmd_tx),
+         * so it has no wakeup to lose. Drop this loop once the POSTING gate in
+         * osi_event_can_post_locked() is fixed (regression in 0564b09e86f). */
+        hci_downstream_data_post(OSI_THREAD_MAX_TIMEOUT);
+    }
+
+    if (kicks == DIRECT_HCI_KICK_MAX &&
+            k_sem_take(&direct_hci_sem, DIRECT_HCI_WAIT_REST) != 0) {
         LOG_ERR("[B]DirectHciTimeout[0x%04x]", opcode);
         return BTM_ERR_PROCESSING;
     }

components/bt/esp_ble_iso/host/common/iso.c

@@ -44,6 +44,17 @@ LOG_MODULE_REGISTER(ISO_SHIM, CONFIG_BT_ISO_LOG_LEVEL);
 #define ISO_PKT_COMP_SDU        (0b10)
 #define ISO_PKT_LAST_FRAG       (0b11)
 
+/* Both callbacks that feed the iso task from the controller task (iso_tx_comp_cb,
+ * bt_le_iso_rx) can fail to hand off an item, and neither may log there:
+ * esp_log_write is a blocking UART write (~3 ms/line at 115200), so reporting at
+ * the failure rate would spend most of a second inside it and deepen the very
+ * congestion it reports. They only count; the matching iso-task handler reports
+ * once every ISO_DROP_REPORT_STEP items, by which point the queue has room again
+ * so the report never competes with the burst that caused it. Causes are counted
+ * apart because they need different fixes: a full queue means the iso task is
+ * behind, a failed alloc means the heap is exhausted. */
+#define ISO_DROP_REPORT_STEP    100
+
 static BT_ISO_EXT_RAM_BSS_ATTR sys_slist_t iso_cbs;
 
 #if CONFIG_BT_ISO_UNICAST
@@ -636,6 +647,11 @@ struct iso_tx_comp_event {
     struct bt_iso_tx_cb_info info;
 };
 
+/* See ISO_DROP_REPORT_STEP. */
+static BT_ISO_CTRL_BSS_ATTR uint32_t iso_tx_comp_drop_cnt;   /* task queue full */
+static BT_ISO_CTRL_BSS_ATTR uint32_t iso_tx_comp_nomem_cnt;  /* evt alloc failed */
+static BT_ISO_CTRL_BSS_ATTR uint32_t iso_tx_comp_reported;
+
 void bt_le_iso_handle_tx_comp(uint8_t *data, size_t data_len)
 {
     struct iso_tx_comp_event *evt = (struct iso_tx_comp_event *)data;
@@ -644,11 +660,19 @@ void bt_le_iso_handle_tx_comp(uint8_t *data, size_t data_len)
     struct bt_conn *iso;
     bt_conn_tx_cb_t cb;
     sys_snode_t *node;
+    uint32_t dropped;
     void *ud;
     int err;
 
     BT_LE_ASSERT(data && data_len == sizeof(*evt));
 
+    dropped = iso_tx_comp_drop_cnt + iso_tx_comp_nomem_cnt;
+    if (dropped - iso_tx_comp_reported >= ISO_DROP_REPORT_STEP) {
+        iso_tx_comp_reported = dropped;
+        LOG_WRN("IsoTxCompDrop[q=%u][nomem=%u]",
+                iso_tx_comp_drop_cnt, iso_tx_comp_nomem_cnt);
+    }
+
     bt_le_host_lock();
 
     while (1) {
@@ -724,7 +748,7 @@ static void iso_tx_comp_cb(uint16_t conn_handle, void *info, size_t size)
 
     evt = bt_le_int_calloc(1, sizeof(*evt));
     if (evt == NULL) {
-        LOG_ERR("IsoTxCompNoMem[%u]", sizeof(*evt));
+        iso_tx_comp_nomem_cnt++;
         return;
     }
 
@@ -733,7 +757,7 @@ static void iso_tx_comp_cb(uint16_t conn_handle, void *info, size_t size)
 
     err = bt_le_iso_task_post(ISO_QUEUE_ITEM_TYPE_ISO_TX_COMP, evt, sizeof(*evt));
     if (err) {
-        LOG_ERR("IsoTxCompPostFail[%d]", err);
+        iso_tx_comp_drop_cnt++;
         free(evt);
     }
 }
@@ -746,12 +770,24 @@ void bt_le_iso_handle_tx_comp(uint8_t *data, size_t data_len)
 #endif /* CONFIG_BT_ISO_TX */
 
 #if CONFIG_BT_ISO_RX
+/* See ISO_DROP_REPORT_STEP. */
+static BT_ISO_CTRL_BSS_ATTR uint32_t iso_rx_drop_cnt;   /* task queue full */
+static BT_ISO_CTRL_BSS_ATTR uint32_t iso_rx_nomem_cnt;  /* rx_data alloc failed */
+static BT_ISO_CTRL_BSS_ATTR uint32_t iso_rx_reported;
+
 void bt_le_iso_handle_rx_data(uint8_t *data, size_t data_len)
 {
     struct net_buf buf = {0};
+    uint32_t dropped;
 
     BT_LE_ASSERT(data && data_len);
 
+    dropped = iso_rx_drop_cnt + iso_rx_nomem_cnt;
+    if (dropped - iso_rx_reported >= ISO_DROP_REPORT_STEP) {
+        iso_rx_reported = dropped;
+        LOG_WRN("IsoRxDrop[q=%u][nomem=%u]", iso_rx_drop_cnt, iso_rx_nomem_cnt);
+    }
+
     bt_le_host_lock();
     net_buf_simple_init_with_data(&buf.b, (void *)data, data_len);
     hci_iso(&buf);
@@ -778,7 +814,7 @@ int bt_le_iso_rx(const uint8_t *data, uint16_t len, void *arg)
 
     rx_data = bt_le_int_calloc(1, len);
     if (rx_data == NULL) {
-        LOG_ERR("IsoRxNoMem[%u]", len);
+        iso_rx_nomem_cnt++;
         return -ENOMEM;
     }
 
@@ -786,7 +822,7 @@ int bt_le_iso_rx(const uint8_t *data, uint16_t len, void *arg)
 
     err = bt_le_iso_task_post(ISO_QUEUE_ITEM_TYPE_ISO_RX_DATA, rx_data, len);
     if (err) {
-        LOG_ERR("IsoRxPostFail[%d]", err);
+        iso_rx_drop_cnt++;
         free(rx_data);
         return -EIO;
     }

components/bt/esp_ble_iso/include/zephyr/kernel.h

@@ -140,7 +140,8 @@ static inline void k_sem_delete(struct k_sem *sem)
 #define K_SEM_LOG_ERR(fmt, args...)     BT_ISO_LOGE("ISO_SEM", fmt, ## args)
 #endif
 
-static inline int k_sem_take(struct k_sem *sem, uint32_t timeout)
+/* Implementation of k_sem_take; call through the macro below. */
+static inline int k_sem_take_dbg(struct k_sem *sem, uint32_t timeout, const char *func)
 {
     BT_LE_ASSERT(sem);
     BT_LE_ASSERT(sem->handle);
@@ -156,13 +157,28 @@ static inline int k_sem_take(struct k_sem *sem, uint32_t timeout)
     }
 
 #if !CONFIG_BT_ISO_NO_LOG && (CONFIG_BT_ISO_LOG_LEVEL >= BT_ISO_LOG_ERROR)
-    K_SEM_LOG_ERR("TakeFail[self=%s]", pcTaskGetName(NULL));
+    K_SEM_LOG_ERR("TakeFail[%s][%s]", func, pcTaskGetName(NULL));
 #else
+    ARG_UNUSED(func);
     K_SEM_LOG_ERR("TakeFail");
 #endif
     return -EIO;
 }
 
+/* Macro, not a wrapper function, so __func__ names the CALLER — that identifies
+ * both the wedged operation and the sem, with no per-sem RAM. */
+#define k_sem_take(sem, timeout)    k_sem_take_dbg((sem), (timeout), __func__)
+
+/* Silent take for slice-polling callers, where only the final expiry is an error
+ * and k_sem_take would log TakeFail per slice. Same sem->result contract. */
+static inline int k_sem_take_poll(struct k_sem *sem, uint32_t timeout)
+{
+    BT_LE_ASSERT(sem);
+    BT_LE_ASSERT(sem->handle);
+
+    return (xSemaphoreTake(sem->handle, timeout) == pdTRUE) ? 0 : -EIO;
+}
+
 static inline int k_sem_give(struct k_sem *sem)
 {
     BT_LE_ASSERT(sem);