8000 ESP32-C3: NimBLE_Arduino v2.3.0 - onStatus reports ATT_ERR_UNLIKELY (code 14) for Indications Despite Successful Data Reception by Client · Issue #970 · h2zero/NimBLE-Arduino · GitHub
[go: up one dir, main page]
Skip to content

ESP32-C3: NimBLE_Arduino v2.3.0 - onStatus reports ATT_ERR_UNLIKELY (code 14) for Indications Despite Successful Data Reception by Client #970

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Open
HAETES opened this issue May 26, 2025 · 1 comment
Open

ESP32-C3: NimBLE_Arduino v2.3.0 - onStatus reports ATT_ERR_UNLIKELY (code 14) for Indications Despite Successful Data Reception by Client #970

HAETES opened this issue May 26, 2025 · 1 comment

Comments

@HAETES
Copy link
HAETES commented May 26, 2025

Observed Behavior:

When sending a series of BLE indications from an ESP32-C3 to an Android client, the onStatus callback of NimBLECharacteristicCallbacks on the ESP32 consistently reports error code=14 (ATT_ERR_UNLIKELY). This occurs for every indication successfully queued with indicate() (which returns true).

Despite this error code being reported on the ESP32 after each indication attempt, the actual data payload of the indication is successfully received and processed by the Android client. All buffered log messages (e.g., 8 messages of varying lengths, all well within MTU limits) are transferred if the onStatus callback is modified to treat code=14 as a trigger to consume the sent message and attempt to send the next one.

If code=14 is treated as a fatal error in onStatus (i.e., not consuming the message and not trying to send the next buffered item), the log transmission stalls after the first attempt.

Hardware & Software Environment:

  • Microcontroller: ESP32-C3 (esp32-c3-devkitm-1)
  • Arduino Core Version: [Please specify your ESP32 Arduino Core version, e.g., 2.0.14 or 3.0.0 - visible in PlatformIO build logs or Arduino IDE Boards Manager]
  • NimBLE-Arduino Version: h2zero/NimBLE-Arduino@2.3.0
  • Development Environment: PlatformIO
  • Client Device: mmotorola edge 30 pro XT2201-1
  • Client Android Version: Android 14
  • Client BLE Library: Kable 0.37.1

platformio.ini Configuration:

[env:esp32-c3-devkitm-1]
platform = espressif32
board = esp32-c3-devkitm-1
framework = arduino
monitor_speed = 115200
board_build.flash_size = 4MB

lib_deps =
    h2zero/NimBLE-Arduino@2.3.0

board_build.sdkconfig_options =
    CONFIG_BT_ENABLED=y
    CONFIG_BT_BLUEDROID_ENABLED=n
    CONFIG_BT_NIMBLE_ENABLED=y
    CONFIG_BTDM_CTRL_MODE_BLE_ONLY=y
    CONFIG_BTDM_CTRL_MODE_BR_EDR_ONLY=n
    CONFIG_BTDM_CTRL_MODE_BTDM=n
    CONFIG_BLE_MESH_ENABLED=n

build_flags =
    -D ARDUINO_USB_MODE=1
    -D ARDUINO_USB_CDC_ON_BOOT=1
    -DCONFIG_BT_NIMBLE_MESH=0
Log Summary:

ESP32 Log Sequence for each indication sent:

LOG_TRY_SEND_STATUS: SysInit:1, BleConf:1, Mutex:OK, ClientConn:1, IndEn:1, IndInProg:0, BufCnt:X (X > 0)
LOG_TSB_DETAIL: Vor indicate(). Log: <log_content>, Länge: <log_length>
LOG_TSB_DETAIL: Nach indicate(). Success: 1. g_indication_in_progress: 1
(approx. 14-15ms later) LOG_CPP: Log CallbacksInternal: code=14 () (from onStatus)
(If not handled as success) LOG_CPP_BLE_ERR: Log Indication Error: code=14 ()
Corresponding Android Logcat (for each indication):

Notification received for observeNotifications ... from Peripheral(...): <log_length> bytes.
Rohdaten von '<DeviceName>': <log_content>
The received <log_content> and <log_length> match what the ESP32 intended to send.
Details:

The MTU is negotiated to 250 bytes.
The indication payload (log string) length is confirmed to be less than ATT_MTU - 3 (e.g., tested with logs ranging from 49 to 87 bytes).
The issue persists across multiple connection cycles.
The indicate() method consistently returns true.
The onStatus callback is consistently invoked with code=14.
Expected Behavior:

The onStatus callback should receive INDICATION_SUCCESS_CODE (0) after the client successfully receives and acknowledges the indication, allowing for a reliable flow control for sending subsequent buffered indications.

Questions:

What are known potential causes for ATT_ERR_UNLIKELY (code=14) in the onStatus callback for an indication, especially when the data transfer to the client appears successful?
Could this indicate a timing issue or a problem in how the NimBLE stack on ESP32-C3 (with v2.3.0) handles indication acknowledgements from certain Android BLE stacks/clients?
Are there any specific NimBLE configurations (beyond standard security and characteristic setup) or known issues with the ESP32-C3 radio/modem firmware that might contribute to this behavior?
Thank you for your time and assistance.


Relevant Code Snippets from ESP32 Firmware:

This summary showcases the setup and usage of the logging characteristic that sends indications and encounters the onStatus code=14 issue.

1. log.h - Definitions for Logging Service and Characteristic:

C++

// In Datei: log.h

#ifndef LOG_H
#define LOG_H

#include <NimBLEDevice.h>

extern const char* BLE_LOG_TAG; // Defined in main.cpp as "T04"
#define BLE_LOG_MAX_FORMATTED_LENGTH 230 // Adjusted to be <= (ATT_MTU - 3 - overhead)
#define LOG_ENTRY_MAX_SIZE_FINAL_CPP (BLE_LOG_MAX_FORMATTED_LENGTH + 1) // Buffer size for a single log entry

#define BLE_LOG_SERVICE_UUID "54FF0100-679F-4A7C-B4E6-B3A21992C251"
#define BLE_LOG_CHAR_DATA_UUID "54FF0101-679F-4A7C-B4E6-B3A21992C25
8000
1"

#define LOG_CCCD_INDICATE_ENABLED 0x0002
static constexpr uint16_t LOG_DATA_CHAR_PROPERTIES = NIMBLE_PROPERTY::INDICATE;

// Public API
void log_system_init(void);
bool log_ble_configure(NimBLEService* pServiceForLogChar);
void ble_log(int level, const char* format, ...);
void printWithTime(const char* tag, const char* format, ...); // For serial debugging only
void log_on_ble_connect(uint16_t conn_handle);
void log_on_ble_disconnect(uint16_t conn_handle);
void log_try_send_buffered(void);

#endif // LOG_H
2. main.cpp - Initialization Sequence:

C++

// In Datei: main.cpp
#include <Arduino.h>
#include <NimBLEDevice.h>
#include "nvs_flash.h"
#include "log.h"
#include "system_service.h" // Also used, but not detailed here for brevity
#include "ble_connection.h"

#define DEVICE_NAME "BleCoMMTestServer03"
const char* BLE_LOG_TAG = "T04";

NimBLEServer* pServer = nullptr;
BleConnection* g_pBleConnection = nullptr;

void setup() {
    Serial.begin(115200);
    delay(5000);
    log_system_init(); // Initializes log buffer and mutex
    ble_log(3, "SYSTEM_START: Serielle Ausgabe und Log-Puffer initialisiert.");

    // ... (NVS Init) ...

    NimBLEDevice::init(DEVICE_NAME);
    NimBLEDevice::setMTU(250); // MTU set to 250

    pServer = NimBLEDevice::createServer();

    g_pBleConnection = new BleConnection(); // Implements NimBLEServerCallbacks
    if (g_pBleConnection) {
        pServer->setCallbacks(g_pBleConnection);
        g_pBleConnection->initializeSecurity(); // Sets bonding, MITM, SC, IO Caps
    } // ... error handling ...

    // Create Log Service
    NimBLEService* pActualLogService = pServer->createService(BLE_LOG_SERVICE_UUID);
    // ... error handling ...

    // Configure Log Module with the service (creates characteristic)
    if (log_ble_configure(pActualLogService) == false) {
        // ... error handling ...
    }
    pActualLogService->start();

    // ... (System Service Init) ...

    // Setup Advertising
    NimBLEAdvertising* pAdvertising = NimBLEDevice::getAdvertising();
    pAdvertising->addServiceUUID(BLE_LOG_SERVICE_UUID);
    // ... (add other service UUIDs, scan response, start advertising) ...
    pAdvertising->start();
    ble_log(3, "SYS_INIT_NIMBLE; %s Setup komplett, Advertising aktiv.", DEVICE_NAME);
}

void loop() {
    // Kept empty for this test
}
3. ble_connection.cpp - Server Callbacks (relevant parts):
(Showing how log_on_ble_connect etc. are called)

C++

// In Datei: ble_connection.cpp
#include "ble_connection.h"
#include "log.h"
#include "system_service.h"
// ...

void BleConnection::onConnect(NimBLEServer* pServer, NimBLEConnInfo& connInfo) {
    m_conn_handle = connInfo.getConnHandle();
    // ... (Serial print) ...
    
    log_on_ble_connect(m_conn_handle); // Notifies log module of connection
    system_service_on_connect(pServer, connInfo);
    // ...
}

void BleConnection::onDisconnect(NimBLEServer* pServer, NimBLEConnInfo& connInfo, int reason) {
    uint16_t disconnected_handle = connInfo.getConnHandle();
    // ... (Serial print) ...
    
    log_on_ble_disconnect(disconnected_handle); // Notifies log module
    system_service_on_disconnect(connInfo, reason);
    // ... (Reset m_conn_handle, restart advertising) ...
}

void BleConnection::onMTUChange(uint16_t MTU, NimBLEConnInfo& connInfo) {
    // ... (Serial print) ...
    ble_log(3, "MTU_CHANGE_CB:MTU:%d,Handle:%d,Addr:%s", MTU, connInfo.getConnHandle(), connInfo.getAddress().toString().c_str());
}

// ... (Other security callbacks like onPassKeyDisplay, onAuthenticationComplete also call ble_log for events) ...
4. log.cpp - Core Logging Logic:

log_ble_configure():

C++

// (Ensures log_system_init is called)
// ...
pLogDataChar_s = pLogService_s->createCharacteristic(
    BLE_LOG_CHAR_DATA_UUID,
    LOG_DATA_CHAR_PROPERTIES // Uses NIMBLE_PROPERTY::INDICATE
);
// ... (Error check) ...
pLogDataChar_s->setCallbacks(&g_logDataCharCallbacks); // g_logDataCharCallbacks is an instance of LogDataCharCallbacksInternal_CPP
g_log_ble_configured_s = true;
// log_try_send_buffered(); // This call was removed to reduce recursion triggers
ble_log():

C++

void ble_log(int level, const char* format, ...) {
    // ... (Checks g_log_system_initialized_s) ...
    // Formats the log string into final_log_string (e.g., "timestamp;T04;level;message")
    // Ensures final_log_string length respects LOG_ENTRY_MAX_SIZE_FINAL_CPP based on BLE_LOG_MAX_FORMATTED_LENGTH
    // ... (vsnprintf and snprintf logic) ...
    internal_add_log_to_buffer(final_log_string);
    // printWithTime("BLE:LOG", "BLE-Log-Eintrag: %s", final_log_string); // Serial echo of what's buffered
    // No call to log_try_send_buffered() here in the current version
}
LogDataCharCallbacksInternal_CPP::onSubscribe():

C++

void onSubscribe(NimBLECharacteristic* pCharacteristic, NimBLEConnInfo& connInfo, uint16_t subValue) override {
    if (pCharacteristic == pLogDataChar_s) {
        if (subValue & LOG_CCCD_INDICATE_ENABLED) {
            g_log_indications_enabled_s = true;
            printWithTime("LOG_CPP", "Client (handle %d) hat Log Indications AKTIVIERT.", connInfo.getConnHandle());
            log_try_send_buffered(); // Primary trigger to start sending from buffer
        } else {
            g_log_indications_enabled_s = false;
            // ...
        }
    }
}
LogDataCharCallbacksInternal_CPP::onStatus() (Version that treats code 14 as "success" for testing to send all logs):

C++

void onStatus(NimBLECharacteristic* pCharacteristic, int code) override {
    printWithTime("LOG_CPP", "Log CallbacksInternal: code=%d (%s)", code, NimBLEUtils::returnCodeToString(code));
    if (pCharacteristic == pLogDataChar_s) {
        if (g_indication_in_progress_s) {
            if (code == INDICATION_SUCCESS_CODE || code == 14) { // Test: Treat code 14 as success
                if(code == 14) {
                    printWithTime("LOG_CPP_BLE_WARN", "Fehler 14 im onStatus, behandle testweise als Erfolg. Log wird konsumiert.");
                } else {
                     printWithTime("LOG_CPP", "Log INDICATION_SUCCESS: code=%d (%s)", code, NimBLEUtils::returnCodeToString(code));
                }
                g_indication_in_progress_s = false;
                // Assuming internal_consume_log_from_buffer() correctly handles mutex
                // if it's the original version, or an _unsafe version is called after taking mutex here.
                // For this summary, we assume the version from the user's last log.cpp which still had:
                internal_consume_log_from_buffer(); // This version takes mutex itself.
                log_try_send_buffered(); // Trigger next send
            } else { // Other actual errors
                g_indication_in_progress_s = false;
                printWithTime("LOG_CPP_BLE_ERR", "Log Indication Error: code=%d (%s)", code, NimBLEUtils::returnCodeToString(code));
            }
        } // ...
    }
}
log_try_send_buffered() (Version that fixed "peek returned NULL" and includes debug logs):

C++

void log_try_send_buffered(void) {
    printWithTime("LOG_TRY_SEND_STATUS", /* ... status flags ... */);
    bool action_taken_this_call = false;
    if (/* initial checks pass */) {
        if (xSemaphoreTake(log_buffer_mutex_s, (TickType_t)0) == pdTRUE) {
            if (/* conditions to send are met: client connected, indications enabled, not already in progress, buffer not empty */) {
                // const char* log_entry_to_send = internal_peek_log_from_buffer(); // Original call
                const char* log_entry_to_send = log_internal_buffer_final_cpp[log_buffer_read_idx_final_cpp]; // Direct access if internal_peek_log_from_buffer was removed

                // if (log_entry_to_send != NULL) { // This check is now against the direct array access result
                    size_t log_len = strlen(log_entry_to_send);
                    if (log_len > 0 && pLogDataChar_s != NULL) {
                        g_indication_in_progress_s = true;
                        xSemaphoreGive(log_buffer_mutex_s);
                        action_taken_this_call = true;

                        printWithTime("LOG_TSB_DETAIL", "Vor indicate(). Log: %s, Länge: %u", log_entry_to_send, log_len);
                        pLogDataChar_s->setValue((uint8_t*)log_entry_to_send, log_len);
                        bool success = pLogDataChar_s->indicate();
                        printWithTime("LOG_TSB_DETAIL", "Nach indicate(). Success: %d. g_indication_in_progress: %d", success, g_indication_in_progress_s);

                        if (!success) {
                            g_indication_in_progress_s = false;
                            printWithTime("LOG_CPP_BLE_ERR", "pLogDataChar_s->indicate() returned false directly.");
                        }
                    } else { /* handle log_len == 0 or pLogDataChar_s == NULL */ }
                // } else { /* This else (for log_entry_to_send == NULL) might now indicate a different issue if BufCnt > 0 */ }
            }
            if (!action_taken_this_call) {
                xSemaphoreGive(log_buffer_mutex_s);
            }
        }
    }
    return;
}
@h2zero
Copy link
Owner
h2zero commented May 26, 2025

Reason code 14 is BLE_HS_EDONE, it is a success code.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@h2zero @HAETES
0