Send Failed Could not prepare l2cap packet len 248

[marskid]

I used the L2CAP CoC to test the communication speed and found that the maximum speed was between 30-40 KB/s. After adding logs, I frequently encountered the message "ble_l2cap_send returned 6. Retrying shortly..." What is the reason for this?

Hardware：esp32 d0wd v3
code: https://github.com/h2zero/NimBLE-Arduino/blob/master/examples/L2CAP/L2CAP_Client/L2CAP_Client.ino

debug log

ets Jul 29 2019 12:21:46

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff0030,len:4744
load:0x40078000,len:15672
load:0x40080400,len:3152
entry 0x4008059c
Starting L2CAP client example
I NimBLEDevice: BLE Host Task Started
I NimBLEDevice: NimBle host synced.
D NimBLEScan: >> start: duration=25000
D NimBLEScan: Scan started
D NimBLEScan: << start()
I NimBLEScan: New advertiser: c8:28:32:f9:5a:f1
D NimBLEScanCallbacks: Discovered: Name: , Address: c8:28:32:f9:5a:f1, manufacturer data: 8f030a101c0000d4c92f36c35cec
I NimBLEScan: Scan response from: c8:28:32:f9:5a:f1
BLE Advertised Device found: Name: , Address: c8:28:32:f9:5a:f1, manufacturer data: 8f030a101c0000d4c92f36c35cec
I NimBLEScan: New advertiser: 35:ed:64:ed:dc:b2
D NimBLEScanCallbacks: Discovered: Name: , Address: 35:ed:64:ed:dc:b2, manufacturer data: 060001092022ea54ac9141035020bd0fb91a493adab33e9cd88b32bae5
BLE Advertised Device found: Name: , Address: 35:ed:64:ed:dc:b2, manufacturer data: 060001092022ea54ac9141035020bd0fb91a493adab33e9cd88b32bae5
I NimBLEScan: New advertiser: 6d:50:21:6d:af:8f
D NimBLEScanCallbacks: Discovered: Name: , Address: 6d:50:21:6d:af:8f, manufacturer data: 4c0010063d1eec730909, txPower: 12
I NimBLEScan: Scan response from: 6d:50:21:6d:af:8f
BLE Advertised Device found: Name: , Address: 6d:50:21:6d:af:8f, manufacturer data: 4c0010063d1eec730909, txPower: 12
I NimBLEScan: New advertiser: 80:7d:3a:dc:b9:4e
D NimBLEScanCallbacks: Discovered: Name: , Address: 80:7d:3a:dc:b9:4e, serviceUUID: dcbc7255-1e9e-49a0-a360-b0430b6c6905
I NimBLEScan: Scan response from: 80:7d:3a:dc:b9:4e
BLE Advertised Device found: Name: , Address: 80:7d:3a:dc:b9:4e, serviceUUID: dcbc7255-1e9e-49a0-a360-b0430b6c6905
Found the device we're interested in!
D NimBLEScan: >> stop()
D NimBLEScan: << stop()
D NimBLEClient: >> connect(80:7d:3a:dc:b9:4e)
D NimBLEClient: >> handleGapEvent 
D NimBLEClient: >> handleGapEvent 
D NimBLEClient: >> handleGapEvent 
D NimBLEClient: >> handleGapEvent 
I NimBLEClient: mtu update: mtu=527
D NimBLEClientCallbacks: onMTUChange: default
DG NimBLEClient: << handleGapEvent
D NimBLEClient: exchangeMTUCb: status=0, mtu=527
AP connected
D NimBLEClient: >> handleGapEvent 
D NimBLEL2CAPChannel: Computed number of buf_blocks = 60
I NimBLEL2CAPChannel: L2CAP COC 0x0096 initialized w/ L2CAP MTU 5000
D NimBLEClient: << connect()
D NimBLEClient: >> handleGapEvent 
D NimBLEClient: Peer requesting to update connection parameters
D NimBLEClient: MinInterval: 12, MaxInterval: 12, Latency: 0, Timeout: 200
D NimBLEClientCallbacks: onConnParamsUpdateRequest: default
D NimBLEClient: Accepted peer params
D NimBLEL2CAPChannel: handleL2capEvent: handling l2cap event 0
I NimBLEL2CAPChannel: L2CAP COC 0x0096 connected. Local MTU = 5000 [248], remote MTU = 5000 [248].
L2CAP connection established
D NimBLEClient: >> handleGapEvent 
I NimBLEClient: Connection parameters updated.
E (3383) NimBLE: Could not prepare l2cap packet len 248
E (3383) NimBLE: Failed

D NimBLEL2CAPChannel: ble_l2cap_send returned 6. Retrying shortly...
D NimBLEL2CAPChannel: L2CAP COC 0x0096 sent 5000 bytes.
D NimBLEL2CAPChannel: L2CAP COC 0x0096 sent 5000 bytes.
W NimBLEL2CAPChannel: ble_l2cap_send returned BLE_HS_ESTALLED. Next send will wait for unstalled event...
E (7174) NimBLE: Could not prepare l2cap packet len 248
E (7174) NimBLE: Failed

D NimBLEL2CAPChannel: handleL2capEvent: handling l2cap event 4
I NimBLEL2CAPChannel: L2CAP COC 0x0096 transmit unstalled.
E (7176) NimBLE: Could not prepare l2cap packet len 248
E (7186) NimBLE: Failed

D NimBLEL2CAPChannel: ble_l2cap_send returned 6. Retrying shortly...
D NimBLEL2CAPChannel: L2CAP COC 0x0096 sent 5000 bytes.
D NimBLEL2CAPChannel: L2CAP COC 0x0096 sent 5000 bytes.
W NimBLEL2CAPChannel: ble_l2cap_send returned BLE_HS_ESTALLED. Next send will wait for unstalled event...
E (7339) NimBLE: Could not prepare l2cap packet len 248
E (7339) NimBLE: Failed

D NimBLEL2CAPChannel: handleL2capEvent: handling l2cap event 4
I NimBLEL2CAPChannel: L2CAP COC 0x0096 transmit unstalled.
E (7341) NimBLE: Could not prepare l2cap packet len 248
E (7351) NimBLE: Failed

D NimBLEL2CAPChannel: ble_l2cap_send returned 6. Retrying shortly...
D NimBLEL2CAPChannel: L2CAP COC 0x0096 sent 5000 bytes.
D NimBLEL2CAPChannel: L2CAP COC 0x0096 sent 5000 bytes.
W NimBLEL2CAPChannel: ble_l2cap_send returned BLE_HS_ESTALLED. Next send will wait for unstalled event...
E (7489) NimBLE: Could not prepare l2cap packet len 248
E (7489) NimBLE: Failed

D NimBLEL2CAPChannel: handleL2capEvent: handling l2cap event 4
I NimBLEL2CAPChannel: L2CAP COC 0x0096 transmit unstalled.
E (7491) NimBLE: Could not prepare l2cap packet len 248
E (7501) NimBLE: Failed

D NimBLEL2CAPChannel: ble_l2cap_send returned 6. Retrying shortly...

Reproducing the logs requires modifying some code.

src\nimconfig.h

 #define CONFIG_BT_NIMBLE_LOG_LEVEL     (0)
 #define CONFIG_NIMBLE_CPP_LOG_LEVEL 4

src\nimble\nimble\host\src\ble_l2cap_coc.c

static int
ble_l2cap_coc_continue_tx(struct ble_l2cap_chan *chan)
{
    struct ble_l2cap_coc_endpoint *tx;
    uint16_t len;
    uint16_t left_to_send;
    struct os_mbuf *txom;
    struct ble_hs_conn *conn;
    uint16_t sdu_size_offset;
    int rc;

    /* If there is no data to send, just return success */
    tx = &chan->coc_tx;
    if (!tx->sdus[0]) {
        ble_hs_unlock();
        return 0;
    }

    while (tx->credits) {
        sdu_size_offset = 0;

        BLE_HS_LOG(DEBUG, "Available credits %d\n", tx->credits);

        /* lets calculate data we are going to send */
        left_to_send = OS_MBUF_PKTLEN(tx->sdus[0]) - tx->data_offset;

        if (tx->data_offset == 0) {
            sdu_size_offset = BLE_L2CAP_SDU_SIZE;
            left_to_send += sdu_size_offset;
        }

        /* Take into account peer MTU */
        len = min(left_to_send, chan->peer_coc_mps);

        /* Prepare packet */
        txom = ble_hs_mbuf_l2cap_pkt();
        if (!txom) {
            BLE_HS_LOG(ERROR, "Could not prepare l2cap packet len %d", len);   //Change here
            rc = BLE_HS_ENOMEM;
            goto failed;
        }

        if (tx->data_offset == 0) {
            /* First packet needs SDU len first. Left to send */
            uint16_t l = htole16(OS_MBUF_PKTLEN(tx->sdus[0]));

            BLE_HS_LOG(DEBUG, "Sending SDU len=%d\n",
                       OS_MBUF_PKTLEN(tx->sdus[0]));
            rc = os_mbuf_append(txom, &l, sizeof(uint16_t));
            if (rc) {
                rc = BLE_HS_ENOMEM;
                BLE_HS_LOG(ERROR, "Could not append data1 rc=%d", rc);   //Change here
                goto failed;
            }
        }

        /* In data_offset we keep track on what we already sent. Need to remember
         * that for first packet we need to decrease data size by 2 bytes for sdu
         * size
         */
        rc = os_mbuf_appendfrom(txom, tx->sdus[0], tx->data_offset,
                                len - sdu_size_offset);
        if (rc) {
            rc = BLE_HS_ENOMEM;
            BLE_HS_LOG(ERROR, "Could not append data2 rc=%d", rc);  //Change here
            goto failed;
        }

        conn = ble_hs_conn_find_assert(chan->conn_handle);
        rc = ble_l2cap_tx(conn, chan, txom);

        if (rc) {
            /* txom is consumed by l2cap */
            txom = NULL;
            goto failed;
        } else {
            tx->credits--;
            tx->data_offset += len - sdu_size_offset;
        }

        BLE_HS_LOG(DEBUG, "Sent %d bytes, credits=%d, to send %d bytes \n",
                   len, tx->credits,
                   OS_MBUF_PKTLEN(tx->sdus[0]) - tx->data_offset);

        if (tx->data_offset == OS_MBUF_PKTLEN(tx->sdus[0])) {
            BLE_HS_LOG(DEBUG, "Complete package sent\n");
            os_mbuf_free_chain(tx->sdus[0]);
            tx->sdus[0] = NULL;
            tx->data_offset = 0;
            break;
        }
    }

    if (tx->sdus[0]) {
        /* Not complete SDU sent, wait for credits */
        tx->flags |= BLE_L2CAP_COC_FLAG_STALLED;
        ble_hs_unlock();
        return BLE_HS_ESTALLED;
    }

    if (tx->flags & BLE_L2CAP_COC_FLAG_STALLED) {
        tx->flags &= ~BLE_L2CAP_COC_FLAG_STALLED;
        ble_hs_unlock();
        ble_l2cap_event_coc_unstalled(chan, 0);
    } else {
        ble_hs_unlock();
    }

    return 0;

failed:
    BLE_HS_LOG(ERROR, "Failed\n");   //Change here
    os_mbuf_free_chain(tx->sdus[0]);
    tx->sdus[0] = NULL;

    os_mbuf_free_chain(txom);
    if (tx->flags & BLE_L2CAP_COC_FLAG_STALLED) {
        tx->flags &= ~BLE_L2CAP_COC_FLAG_STALLED;
        ble_hs_unlock();
        ble_l2cap_event_coc_unstalled(chan, rc);
    } else {
        ble_hs_unlock();
    }

    return rc;
}

[h2zero]

Possibly related to #1041

Please try the fix suggested there and let me know.

[marskid]

MSYS_1_BLOCK_SIZE and MSYS1_BLOCK_COUNT resolve issue

#define CONFIG_BT_NIMBLE_MSYS1_BLOCK_COUNT  24
#define CONFIG_BT_NIMBLE_MSYS_1_BLOCK_SIZE  512

#1041 can't fix that.

/** @brief ACL Buffer size */
#define CONFIG_BT_NIMBLE_TRANSPORT_ACL_SIZE 512  // can't fix