diff --git a/connectivity/FEATURE_BLE/source/CMakeLists.txt b/connectivity/FEATURE_BLE/source/CMakeLists.txt index 11ed260a9b..fed9070f32 100644 --- a/connectivity/FEATURE_BLE/source/CMakeLists.txt +++ b/connectivity/FEATURE_BLE/source/CMakeLists.txt @@ -7,6 +7,11 @@ add_subdirectory(gatt) add_subdirectory(generic) add_subdirectory(pal) +target_include_directories(mbed-ble + INTERFACE + . +) + target_sources(mbed-ble INTERFACE BLE.cpp @@ -14,6 +19,7 @@ target_sources(mbed-ble GattClient.cpp GattServer.cpp SecurityManager.cpp + common/ble_trace_helpers.cpp ) target_link_libraries(mbed-ble diff --git a/connectivity/FEATURE_BLE/source/common/ble_trace_helpers.cpp b/connectivity/FEATURE_BLE/source/common/ble_trace_helpers.cpp index 7c15eed165..f26396af61 100644 --- a/connectivity/FEATURE_BLE/source/common/ble_trace_helpers.cpp +++ b/connectivity/FEATURE_BLE/source/common/ble_trace_helpers.cpp @@ -16,10 +16,192 @@ */ #include "ble_trace_helpers.h" +#include "pal/AttServerMessage.h" +#include "ble-host/include/att_api.h" #define TRACE_GROUP "BLE " namespace ble { #if MBED_CONF_MBED_TRACE_ENABLE + +const char* ble_error_to_string(ble_error_t error_code) +{ +#if MBED_CONF_BLE_TRACE_HUMAN_READABLE_ENUMS + const char* ret = "INVALID ENUM VALUE"; + switch(error_code) + { + case BLE_ERROR_NONE: ret = "BLE_ERROR_NONE"; break; + case BLE_ERROR_BUFFER_OVERFLOW: ret = "BLE_ERROR_BUFFER_OVERFLOW"; break; + case BLE_ERROR_NOT_IMPLEMENTED: ret = "BLE_ERROR_NOT_IMPLEMENTED"; break; + case BLE_ERROR_PARAM_OUT_OF_RANGE: ret = "BLE_ERROR_PARAM_OUT_OF_RANGE"; break; + case BLE_ERROR_INVALID_PARAM: ret = "BLE_ERROR_INVALID_PARAM"; break; + case BLE_STACK_BUSY: ret = "BLE_STACK_BUSY"; break; + case BLE_ERROR_INVALID_STATE: ret = "BLE_ERROR_INVALID_STATE"; break; + case BLE_ERROR_NO_MEM: ret = "BLE_ERROR_NO_MEM"; break; + case BLE_ERROR_OPERATION_NOT_PERMITTED: ret = "BLE_ERROR_OPERATION_NOT_PERMITTED"; break; + case BLE_ERROR_INITIALIZATION_INCOMPLETE: ret = "BLE_ERROR_INITIALIZATION_INCOMPLETE"; break; + case BLE_ERROR_ALREADY_INITIALIZED: ret = "BLE_ERROR_ALREADY_INITIALIZED"; break; + case BLE_ERROR_UNSPECIFIED: ret = "BLE_ERROR_UNSPECIFIED"; break; + case BLE_ERROR_INTERNAL_STACK_FAILURE: ret = "BLE_ERROR_INTERNAL_STACK_FAILURE"; break; + case BLE_ERROR_NOT_FOUND: ret = "BLE_ERROR_NOT_FOUND"; break; + } +#else // MBED_CONF_BLE_TRACE_HUMAN_READABLE_ENUMS + static char ret[3] = "00"; + sprintf(ret, "0x%02x", (int)error_code); +#endif // MBED_CONF_BLE_TRACE_HUMAN_READABLE_ENUMS + return ret; +} + +const char* attribute_error_code_to_string(uint8_t error_code) +{ +#if MBED_CONF_BLE_TRACE_HUMAN_READABLE_ENUMS + const char* ret = "INVALID ENUM VALUE"; + switch(error_code) + { + case AttErrorResponse::INVALID_HANDLE: ret = "INVALID_HANDLE"; break; + case AttErrorResponse::READ_NOT_PERMITTED: ret = "READ_NOT_PERMITTED"; break; + case AttErrorResponse::WRITE_NOT_PERMITTED: ret = "WRITE_NOT_PERMITTED"; break; + case AttErrorResponse::INVALID_PDU: ret = "INVALID_PDU"; break; + case AttErrorResponse::INSUFFICIENT_AUTHENTICATION: ret = "INSUFFICIENT_AUTHENTICATION"; break; + case AttErrorResponse::REQUEST_NOT_SUPPORTED: ret = "REQUEST_NOT_SUPPORTED"; break; + case AttErrorResponse::INVALID_OFFSET: ret = "INVALID_OFFSET"; break; + case AttErrorResponse::INSUFFICIENT_AUTHORIZATION: ret = "INSUFFICIENT_AUTHORIZATION"; break; + case AttErrorResponse::PREPARE_QUEUE_FULL: ret = "PREPARE_QUEUE_FULL"; break; + case AttErrorResponse::ATTRIBUTE_NOT_FOUND: ret = "ATTRIBUTE_NOT_FOUND"; break; + case AttErrorResponse::ATTRIBUTE_NOT_LONG: ret = "ATTRIBUTE_NOT_LONG"; break; + case AttErrorResponse::INSUFFICIENT_ENCRYPTION_KEY_SIZE: ret = "INSUFFICIENT_ENCRYPTION_KEY_SIZE"; break; + case AttErrorResponse::INVALID_ATTRIBUTE_VALUE_LENGTH: ret = "INVALID_ATTRIBUTE_VALUE_LENGTH"; break; + case AttErrorResponse::UNLIKELY_ERROR: ret = "UNLIKELY_ERROR"; break; + case AttErrorResponse::INSUFFICIENT_ENCRYPTION: ret = "INSUFFICIENT_ENCRYPTION"; break; + case AttErrorResponse::UNSUPPORTED_GROUP_TYPE: ret = "UNSUPPORTED_GROUP_TYPE"; break; + case AttErrorResponse::INSUFFICIENT_RESOURCES: ret = "INSUFFICIENT_RESOURCES"; break; + case AttErrorResponse::WRITE_REQUEST_REJECTED: ret = "WRITE_REQUEST_REJECTED"; break; + case AttErrorResponse::CLIENT_CHARACTERISTIC_CONFIGURATION_DESCRIPTOR_IMPROPERLY_CONFIGURED: + ret = "CLIENT_CHARACTERISTIC_CONFIGURATION_DESCRIPTOR_IMPROPERLY_CONFIGURED"; break; + case AttErrorResponse::PROCEDURE_ALREADY_IN_PROGRESS: ret = "PROCEDURE_ALREADY_IN_PROGRESS"; break; + case AttErrorResponse::OUT_OF_RANGE: ret = "OUT_OF_RANGE"; break; + } +#else // MBED_CONF_BLE_TRACE_HUMAN_READABLE_ENUMS + static char ret[3] = "00"; + sprintf(ret, "0x%02x", (int)error_code); +#endif // MBED_CONF_BLE_TRACE_HUMAN_READABLE_ENUMS + return ret; +} + +const char* att_client_callback_event_to_string(uint8_t code) +{ +#if MBED_CONF_BLE_TRACE_HUMAN_READABLE_ENUMS + const char* ret = "INVALID EVENT"; + switch(code) + { + case ATTC_FIND_INFO_RSP: ret = "ATTC_FIND_INFO_RSP"; break; + case ATTC_FIND_BY_TYPE_VALUE_RSP: ret = "ATTC_FIND_BY_TYPE_VALUE_RSP"; break; + case ATTC_READ_BY_TYPE_RSP: ret = "ATTC_READ_BY_TYPE_RSP"; break; + case ATTC_READ_RSP: ret = "ATTC_READ_RSP"; break; + case ATTC_READ_LONG_RSP: ret = "ATTC_READ_LONG_RSP"; break; + case ATTC_READ_MULTIPLE_RSP: ret = "ATTC_READ_MULTIPLE_RSP"; break; + case ATTC_READ_BY_GROUP_TYPE_RSP: ret = "ATTC_READ_BY_GROUP_TYPE_RSP"; break; + case ATTC_WRITE_RSP: ret = "ATTC_WRITE_RSP"; break; + case ATTC_WRITE_CMD_RSP: ret = "ATTC_WRITE_CMD_RSP"; break; + case ATTC_PREPARE_WRITE_RSP: ret = "ATTC_PREPARE_WRITE_RSP"; break; + case ATTC_EXECUTE_WRITE_RSP: ret = "ATTC_EXECUTE_WRITE_RSP"; break; + case ATTC_HANDLE_VALUE_NTF: ret = "ATTC_HANDLE_VALUE_NTF"; break; + case ATTC_HANDLE_VALUE_IND: ret = "ATTC_HANDLE_VALUE_IND"; break; + case ATTC_READ_MULT_VAR_RSP: ret = "ATTC_READ_MULT_VAR_RSP"; break; + case ATTC_MULT_VALUE_NTF: ret = "ATTC_MULT_VALUE_NTF"; break; + case ATTS_HANDLE_VALUE_CNF: ret = "ATTS_HANDLE_VALUE_CNF"; break; + case ATTS_MULT_VALUE_CNF: ret = "ATTS_MULT_VALUE_CNF"; break; + case ATTS_CCC_STATE_IND: ret = "ATTS_CCC_STATE_IND"; break; + case ATTS_DB_HASH_CALC_CMPL_IND: ret = "ATTS_DB_HASH_CALC_CMPL_IND"; break; + case ATT_MTU_UPDATE_IND: ret = "ATT_MTU_UPDATE_IND"; break; + case ATT_EATT_CONN_CMPL_IND: ret = "ATT_EATT_CONN_CMPL_IND"; break; + case ATT_EATT_RECONFIG_CMPL_IND: ret = "ATT_EATT_RECONFIG_CMPL_IND"; break; + } +#else // MBED_CONF_BLE_TRACE_HUMAN_READABLE_ENUMS + static char ret[3] = "00"; + sprintf(ret, "0x%02x", (int)code); +#endif // MBED_CONF_BLE_TRACE_HUMAN_READABLE_ENUMS + return ret; +} + +const char* att_error_code_to_string(uint8_t error_code) +{ +#if MBED_CONF_BLE_TRACE_HUMAN_READABLE_ENUMS + const char* ret = "INVALID EVENT"; + switch(error_code) + { + case ATT_SUCCESS: ret = "ATT_SUCCESS"; break; + case ATT_ERR_HANDLE: ret = "ATT_ERR_HANDLE"; break; + case ATT_ERR_READ: ret = "ATT_ERR_READ"; break; + case ATT_ERR_WRITE: ret = "ATT_ERR_WRITE"; break; + case ATT_ERR_INVALID_PDU: ret = "ATT_ERR_INVALID_PDU"; break; + case ATT_ERR_AUTH: ret = "ATT_ERR_AUTH"; break; + case ATT_ERR_NOT_SUP: ret = "ATT_ERR_NOT_SUP"; break; + case ATT_ERR_OFFSET: ret = "ATT_ERR_OFFSET"; break; + case ATT_ERR_AUTHOR: ret = "ATT_ERR_AUTHOR"; break; + case ATT_ERR_QUEUE_FULL: ret = "ATT_ERR_QUEUE_FULL"; break; + case ATT_ERR_NOT_FOUND: ret = "ATT_ERR_NOT_FOUND"; break; + case ATT_ERR_NOT_LONG: ret = "ATT_ERR_NOT_LONG"; break; + case ATT_ERR_KEY_SIZE: ret = "ATT_ERR_KEY_SIZE"; break; + case ATT_ERR_LENGTH: ret = "ATT_ERR_LENGTH"; break; + case ATT_ERR_UNLIKELY: ret = "ATT_ERR_UNLIKELY"; break; + case ATT_ERR_ENC: ret = "ATT_ERR_ENC"; break; + case ATT_ERR_GROUP_TYPE: ret = "ATT_ERR_GROUP_TYPE"; break; + case ATT_ERR_RESOURCES: ret = "ATT_ERR_RESOURCES"; break; + case ATT_ERR_DATABASE_OUT_OF_SYNC: ret = "ATT_ERR_DATABASE_OUT_OF_SYNC"; break; + case ATT_ERR_VALUE_NOT_ALLOWED: ret = "ATT_ERR_VALUE_NOT_ALLOWED"; break; + case ATT_ERR_WRITE_REJ: ret = "ATT_ERR_WRITE_REJ"; break; + case ATT_ERR_CCCD: ret = "ATT_ERR_CCCD"; break; + case ATT_ERR_IN_PROGRESS: ret = "ATT_ERR_IN_PROGRESS"; break; + case ATT_ERR_RANGE: ret = "ATT_ERR_RANGE"; break; + } +#else // MBED_CONF_BLE_TRACE_HUMAN_READABLE_ENUMS + static char ret[3] = "00"; + sprintf(ret, "0x%02x", (int)error_code); +#endif // MBED_CONF_BLE_TRACE_HUMAN_READABLE_ENUMS + return ret; +} + +const char* attribute_opcode_to_string(uint8_t error_code) +{ +#if MBED_CONF_BLE_TRACE_HUMAN_READABLE_ENUMS + const char* ret = "INVALID OPCODE"; + switch(error_code) + { + case AttributeOpcode::ERROR_RESPONSE: ret = "ERROR_RESPONSE"; break; + case AttributeOpcode::EXCHANGE_MTU_REQUEST: ret = "EXCHANGE_MTU_REQUEST"; break; + case AttributeOpcode::EXCHANGE_MTU_RESPONSE: ret = "EXCHANGE_MTU_RESPONSE"; break; + case AttributeOpcode::FIND_INFORMATION_REQUEST: ret = "FIND_INFORMATION_REQUEST"; break; + case AttributeOpcode::FIND_INFORMATION_RESPONSE: ret = "FIND_INFORMATION_RESPONSE"; break; + case AttributeOpcode::FIND_BY_TYPE_VALUE_REQUEST: ret = "FIND_BY_TYPE_VALUE_REQUEST"; break; + case AttributeOpcode::FIND_BY_VALUE_TYPE_RESPONSE: ret = "FIND_BY_VALUE_TYPE_RESPONSE"; break; + case AttributeOpcode::READ_BY_TYPE_REQUEST: ret = "READ_BY_TYPE_REQUEST"; break; + case AttributeOpcode::READ_BY_TYPE_RESPONSE: ret = "READ_BY_TYPE_RESPONSE"; break; + case AttributeOpcode::READ_REQUEST: ret = "READ_REQUEST"; break; + case AttributeOpcode::READ_RESPONSE: ret = "READ_RESPONSE"; break; + case AttributeOpcode::READ_BLOB_REQUEST: ret = "READ_BLOB_REQUEST"; break; + case AttributeOpcode::READ_BLOB_RESPONSE: ret = "READ_BLOB_RESPONSE"; break; + case AttributeOpcode::READ_MULTIPLE_REQUEST: ret = "READ_MULTIPLE_REQUEST"; break; + case AttributeOpcode::READ_MULTIPLE_RESPONSE: ret = "READ_MULTIPLE_RESPONSE"; break; + case AttributeOpcode::READ_BY_GROUP_TYPE_REQUEST: ret = "READ_BY_GROUP_TYPE_REQUEST"; break; + case AttributeOpcode::READ_BY_GROUP_TYPE_RESPONSE: ret = "READ_BY_GROUP_TYPE_RESPONSE"; break; + case AttributeOpcode::WRITE_REQUEST: ret = "WRITE_REQUEST"; break; + case AttributeOpcode::WRITE_RESPONSE: ret = "WRITE_RESPONSE"; break; + case AttributeOpcode::WRITE_COMMAND: ret = "WRITE_COMMAND"; break; + case AttributeOpcode::SIGNED_WRITE_COMMAND: ret = "SIGNED_WRITE_COMMAND"; break; + case AttributeOpcode::PREPARE_WRITE_REQUEST: ret = "PREPARE_WRITE_REQUEST"; break; + case AttributeOpcode::PREPARE_WRITE_RESPONSE: ret = "PREPARE_WRITE_RESPONSE"; break; + case AttributeOpcode::EXECUTE_WRITE_REQUEST: ret = "EXECUTE_WRITE_REQUEST"; break; + case AttributeOpcode::EXECUTE_WRITE_RESPONSE: ret = "EXECUTE_WRITE_RESPONSE"; break; + case AttributeOpcode::HANDLE_VALUE_NOTIFICATION: ret = "HANDLE_VALUE_NOTIFICATION"; break; + case AttributeOpcode::HANDLE_VALUE_INDICATION: ret = "HANDLE_VALUE_INDICATION"; break; + } +#else // MBED_CONF_BLE_TRACE_HUMAN_READABLE_ENUMS + static char ret[3] = "00"; + sprintf(ret, "0x%02x", (int)error_code); +#endif // MBED_CONF_BLE_TRACE_HUMAN_READABLE_ENUMS + return ret; +} + const char* dm_callback_event_to_string(uint8_t event) { #if MBED_CONF_BLE_TRACE_HUMAN_READABLE_ENUMS const char* ret = "INVALID"; @@ -121,7 +303,7 @@ const char* dm_callback_event_to_string(uint8_t event) { } #else // MBED_CONF_BLE_TRACE_HUMAN_READABLE_ENUMS static char ret[3] = "00"; - sprintf(ret, "%02x", (int)event); + sprintf(ret, "0x%02x", (int)event); #endif // MBED_CONF_BLE_TRACE_HUMAN_READABLE_ENUMS return ret; } @@ -328,7 +510,7 @@ const char* hci_opcode_to_string(uint16_t opcode) } #else // MBED_CONF_BLE_TRACE_HUMAN_READABLE_ENUMS static char ret[3] = "00"; - sprintf(ret, "%02x", (int)opcode); + sprintf(ret, "0x%02x", (int)opcode); #endif // MBED_CONF_BLE_TRACE_HUMAN_READABLE_ENUMS return ret; } diff --git a/connectivity/FEATURE_BLE/source/common/ble_trace_helpers.h b/connectivity/FEATURE_BLE/source/common/ble_trace_helpers.h index b70015718a..26092a4f18 100644 --- a/connectivity/FEATURE_BLE/source/common/ble_trace_helpers.h +++ b/connectivity/FEATURE_BLE/source/common/ble_trace_helpers.h @@ -22,13 +22,20 @@ #include "mbed-trace/mbed_trace.h" #include "pal/GapTypes.h" #include "ble-host/include/dm_api.h" +#include "common/UUID.h" namespace ble { #if MBED_CONF_MBED_TRACE_ENABLE -const char* dm_callback_event_to_string(uint8_t event); void trace_le_supported_features(uint64_t feat); + +const char* dm_callback_event_to_string(uint8_t event); const char* hci_opcode_to_string(uint16_t opcode); +const char* attribute_error_code_to_string(uint8_t error); +const char* attribute_opcode_to_string(uint8_t error); +const char* ble_error_to_string(ble_error_t error); +const char* att_client_callback_event_to_string(uint8_t code); +const char* att_error_code_to_string(uint8_t code); #endif //MBED_CONF_MBED_TRACE_ENABLE template @@ -37,6 +44,11 @@ static inline const char* tr_as_array(T item) return (mbed_trace_array)((const uint8_t*)&item, sizeof(item)); } +static inline const char* to_string(UUID uuid) +{ + return (mbed_trace_array)(uuid.getBaseUUID(), uuid.getLen()); +} + static inline constexpr const char* to_string(bool v) { if (v) { diff --git a/connectivity/FEATURE_BLE/source/cordio/source/PalAttClientImpl.cpp b/connectivity/FEATURE_BLE/source/cordio/source/PalAttClientImpl.cpp index 5eb8622e6e..b9ff561980 100644 --- a/connectivity/FEATURE_BLE/source/cordio/source/PalAttClientImpl.cpp +++ b/connectivity/FEATURE_BLE/source/cordio/source/PalAttClientImpl.cpp @@ -27,6 +27,8 @@ #include "att_api.h" #include "att_defs.h" +#define TRACE_GROUP "BLAT" + namespace ble { namespace impl { @@ -41,6 +43,7 @@ PalAttClient::~PalAttClient() = default; */ ble_error_t PalAttClient::exchange_mtu_request(connection_handle_t connection) { + tr_info("Connection %d - AttcMtuReq mtu=%d", connection, pAttCfg->mtu); AttcMtuReq(connection, pAttCfg->mtu); return BLE_ERROR_NONE; } @@ -65,6 +68,7 @@ ble_error_t PalAttClient::find_information_request( attribute_handle_range_t discovery_range ) { + tr_info("Connection %d - AttcFindInfoReq handles=[%d:%d]", connection_handle, discovery_range.begin, discovery_range.end); AttcFindInfoReq( connection_handle, discovery_range.begin, @@ -84,6 +88,8 @@ ble_error_t PalAttClient::find_by_type_value_request( const Span &value ) { + tr_debug("Connection %d - AttcFindByTypeValueReq handles=[%d:%d] type=%d value=%s", + connection_handle, discovery_range.begin, discovery_range.end, type, tr_array(value.data(), value.size())); AttcFindByTypeValueReq( connection_handle, discovery_range.begin, @@ -105,6 +111,8 @@ ble_error_t PalAttClient::read_by_type_request( const UUID &type ) { + tr_debug("Connection %d - AttcReadByTypeReq handles=[%d:%d] uuid=%s", + connection_handle, read_range.begin, read_range.end, to_string(type)); AttcReadByTypeReq( connection_handle, read_range.begin, @@ -124,6 +132,7 @@ ble_error_t PalAttClient::read_request( attribute_handle_t attribute_handle ) { + tr_debug("Connection %d - AttcReadReq handle=%d", connection_handle, attribute_handle); AttcReadReq(connection_handle, attribute_handle); return BLE_ERROR_NONE; } @@ -137,6 +146,7 @@ ble_error_t PalAttClient::read_blob_request( uint16_t offset ) { + tr_debug("Connection %d - AttcReadLongReq handle=%d offset=%d", connection_handle, attribute_handle, offset); AttcReadLongReq( connection_handle, attribute_handle, @@ -154,6 +164,8 @@ ble_error_t PalAttClient::read_multiple_request( const Span &attribute_handles ) { + tr_debug("Connection %d - AttcReadMultipleReq handles=%s", + connection_handle, tr_array((uint8_t*)attribute_handles.data(), attribute_handles.size())); AttcReadMultipleReq( connection_handle, attribute_handles.size(), @@ -171,6 +183,8 @@ ble_error_t PalAttClient::read_by_group_type_request( const UUID &group_type ) { + tr_debug("Connection %d - AttcReadByGroupTypeReq handles=[%d:%d] uuid=%s", + connection_handle, read_range.begin, read_range.end, to_string(group_type)); AttcReadByGroupTypeReq( connection_handle, read_range.begin, @@ -191,6 +205,8 @@ ble_error_t PalAttClient::write_request( const Span &value ) { + tr_debug("Connection %d - AttcWriteReq handle=%d value=%s", + connection_handle, attribute_handle, tr_array(value.data(), value.size())); AttcWriteReq( connection_handle, attribute_handle, @@ -209,6 +225,8 @@ ble_error_t PalAttClient::write_command( const Span &value ) { + tr_debug("Connection %d - AttcWriteCmd handle=%d value=%s", + connection_handle, attribute_handle, tr_array(value.data(), value.size())); AttcWriteCmd( connection_handle, attribute_handle, @@ -227,6 +245,8 @@ ble_error_t PalAttClient::signed_write_command( const Span &value ) { + tr_debug("Connection %d - AttcSignedWriteCmd handle=%d sign_counter=&d value=%s", + connection_handle, attribute_handle, _local_sign_counter, tr_array(value.data(), value.size())); AttcSignedWriteCmd( connection_handle, attribute_handle, @@ -261,6 +281,8 @@ ble_error_t PalAttClient::prepare_write_request( const Span &value ) { + tr_debug("Connection %d - AttcPrepareWriteReq handle=%d offset=%d value=%s", + connection_handle, attribute_handle, offset, tr_array(value.data(), value.size())); AttcPrepareWriteReq( connection_handle, attribute_handle, @@ -281,6 +303,8 @@ ble_error_t PalAttClient::execute_write_request( bool execute ) { + tr_debug("AttcExecuteWriteReq %d - execute=%s", + connection_handle, to_string(execute)); AttcExecuteWriteReq( connection_handle, execute @@ -396,6 +420,7 @@ void PalAttClient::on_transaction_timeout( connection_handle_t connection_handle ) { + tr_info("Connection %d - transaction timed out", connection_handle); if (_transaction_timeout_cb) { _transaction_timeout_cb(connection_handle); } @@ -404,6 +429,7 @@ void PalAttClient::on_transaction_timeout( #if BLE_FEATURE_GATT_CLIENT void PalAttClient::att_client_handler(const attEvt_t *event) { + tr_debug("ATT event: %s status: %s", att_client_callback_event_to_string(event->hdr.event), att_error_code_to_string(event->hdr.status)); if (event->hdr.status == ATT_SUCCESS && event->hdr.event == ATT_MTU_UPDATE_IND) { ble::impl::BLEInstanceBase &ble = BLEInstanceBase::deviceInstance(); PalGattClientEventHandler *handler = ble.getPalGattClient().get_event_handler(); diff --git a/connectivity/FEATURE_BLE/source/generic/GattClientImpl.cpp b/connectivity/FEATURE_BLE/source/generic/GattClientImpl.cpp index 51330588a1..338f9c59ce 100644 --- a/connectivity/FEATURE_BLE/source/generic/GattClientImpl.cpp +++ b/connectivity/FEATURE_BLE/source/generic/GattClientImpl.cpp @@ -33,6 +33,10 @@ #include "source/pal/AttServerMessage.h" #include "source/BLEInstanceBase.h" +#include "common/ble_trace_helpers.h" + +#define TRACE_GROUP "BLGC" + using ble::AttServerMessage; using ble::AttReadResponse; using ble::AttReadBlobResponse; @@ -113,7 +117,7 @@ struct GattClient::ProcedureControlBlock { /* * Procedure control block for the discovery process. */ - +#define TRACE_CLASS "DiscoveryControlBlock" struct GattClient::DiscoveryControlBlock final : public ProcedureControlBlock { using ProcedureControlBlock::connection_handle; @@ -144,11 +148,13 @@ struct GattClient::DiscoveryControlBlock final : public ProcedureControlBlock { void handle_timeout_error(GattClient *client) final { + tr_warning("%s timed out", TRACE_CLASS); terminate(client); } void abort(GattClient *client) final { + tr_warning("%s aborted", TRACE_CLASS); terminate(client); } @@ -179,6 +185,7 @@ struct GattClient::DiscoveryControlBlock final : public ProcedureControlBlock { case AttributeOpcode::ERROR_RESPONSE: { const auto &error = static_cast(message); if (error.error_code != AttErrorResponse::ATTRIBUTE_NOT_FOUND) { + tr_warning("%s terminating early due to %s", TRACE_CLASS, attribute_error_code_to_string(error.error_code)); terminate(client); return; } @@ -206,6 +213,7 @@ struct GattClient::DiscoveryControlBlock final : public ProcedureControlBlock { void handle_service_discovered(GattClient *client, const Response &response) { if (!response.size()) { + tr_error("%s terminating due to malformed message", TRACE_CLASS); terminate(client); return; } @@ -216,6 +224,8 @@ struct GattClient::DiscoveryControlBlock final : public ProcedureControlBlock { end_handle = get_end_handle(response[i]); UUID uuid = get_uuid(response[i]); + tr_debug("Discovered service UUID: %s [0x%x:0x%x])", to_string(uuid), start_handle, end_handle); + if (!characteristic_callback) { DiscoveredService discovered_service; discovered_service.setup(uuid, start_handle, end_handle); @@ -250,11 +260,13 @@ struct GattClient::DiscoveryControlBlock final : public ProcedureControlBlock { void start_characteristic_discovery(GattClient *client) { if (!services_discovered) { + tr_error("%s terminating due to services list structure null", TRACE_CLASS); terminate(client); return; } if (!characteristic_callback) { + tr_error("%s terminating due missing characteristic callback", TRACE_CLASS); terminate(client); return; } @@ -293,6 +305,7 @@ struct GattClient::DiscoveryControlBlock final : public ProcedureControlBlock { last_characteristic = characteristic_t( client, connection_handle, response[i].handle, response[i].value ); + tr_debug("Discovered char handle: 0x%x value: %s", response[i].handle, tr_array(response[i].value.data(), response[i].value.size())); } // check if all the characteristics of the service has been discovered @@ -308,6 +321,7 @@ struct GattClient::DiscoveryControlBlock final : public ProcedureControlBlock { ); if (err) { + tr_error("%s terminating early due to %s", TRACE_CLASS, ble_error_to_string(err)); terminate(client); } } @@ -328,6 +342,7 @@ struct GattClient::DiscoveryControlBlock final : public ProcedureControlBlock { delete old; if (!services_discovered) { + tr_debug("Service discovery complete"); terminate(client); } else { start_characteristic_discovery(client); @@ -473,7 +488,7 @@ struct GattClient::DiscoveryControlBlock final : public ProcedureControlBlock { bool done; }; - +#define TRACE_CLASS "ReadControlBlock" struct GattClient::ReadControlBlock final : public ProcedureControlBlock { using ProcedureControlBlock::connection_handle; @@ -494,6 +509,7 @@ struct GattClient::ReadControlBlock final : public ProcedureControlBlock { void handle_timeout_error(GattClient *client) final { + tr_warning("%s timed out", TRACE_CLASS); GattReadCallbackParams response = { connection_handle, attribute_handle, @@ -507,6 +523,7 @@ struct GattClient::ReadControlBlock final : public ProcedureControlBlock { void abort(GattClient *client) final { + tr_warning("%s aborted", TRACE_CLASS); GattReadCallbackParams response = { connection_handle, attribute_handle, @@ -543,6 +560,7 @@ struct GattClient::ReadControlBlock final : public ProcedureControlBlock { default: { // should not happen, terminate the procedure and notify client with an error // in such case + tr_error("%s terminated unexpectedly due to unhandled opcode 0x%x", TRACE_CLASS, (int)message.opcode); GattReadCallbackParams response = { connection_handle, attribute_handle, @@ -583,11 +601,13 @@ struct GattClient::ReadControlBlock final : public ProcedureControlBlock { response.len = (current_offset + read_response.size()) - offset; response.data = data; } + tr_info("Read response complete - received %d bytes", read_response.size()); terminate(client, response); } else { // allocation which will contain the response data plus the next one. data = (uint8_t *) realloc(data, (current_offset - offset) + ((mtu_size - 1) * 2)); if (data == nullptr) { + tr_error("%s terminated due to OoM error", TRACE_CLASS); GattReadCallbackParams response = { connection_handle, attribute_handle, @@ -601,6 +621,7 @@ struct GattClient::ReadControlBlock final : public ProcedureControlBlock { } memcpy(data + (current_offset - offset), read_response.data(), read_response.size()); + tr_info("Read response partial - received %d bytes", read_response.size()); current_offset = current_offset + read_response.size(); ble_error_t err = client->_pal_client.read_attribute_blob( connection_handle, @@ -609,6 +630,7 @@ struct GattClient::ReadControlBlock final : public ProcedureControlBlock { ); if (err) { + tr_error("%s terminated because reading attribute failed", TRACE_CLASS); GattReadCallbackParams response = { connection_handle, attribute_handle, @@ -656,6 +678,8 @@ struct GattClient::ReadControlBlock final : public ProcedureControlBlock { break; } + tr_error("%s error: %s", TRACE_CLASS, attribute_error_code_to_string(error.error_code)); + GattReadCallbackParams response = { connection_handle, attribute_handle, @@ -677,7 +701,7 @@ struct GattClient::ReadControlBlock final : public ProcedureControlBlock { /* * Control block for the write process */ - +#define TRACE_CLASS "WriteControlBlock" struct GattClient::WriteControlBlock final : public ProcedureControlBlock { using ProcedureControlBlock::connection_handle; @@ -699,6 +723,7 @@ struct GattClient::WriteControlBlock final : public ProcedureControlBlock { void handle_timeout_error(GattClient *client) final { + tr_warning("%s timed out", TRACE_CLASS); GattWriteCallbackParams response = { connection_handle, attribute_handle, @@ -711,6 +736,7 @@ struct GattClient::WriteControlBlock final : public ProcedureControlBlock { void abort(GattClient *client) final { + tr_warning("%s aborted", TRACE_CLASS); GattWriteCallbackParams response = { connection_handle, attribute_handle, @@ -748,6 +774,8 @@ struct GattClient::WriteControlBlock final : public ProcedureControlBlock { break; default: { + tr_error("%s terminated due unhandled opcode 0x%x", TRACE_CLASS, (int)message.opcode); + GattWriteCallbackParams response = { connection_handle, attribute_handle, @@ -763,6 +791,7 @@ struct GattClient::WriteControlBlock final : public ProcedureControlBlock { void handle_write_response(GattClient* client, const AttWriteResponse& write_response) { + tr_debug("write executed successfully"); GattWriteCallbackParams response = { connection_handle, attribute_handle, @@ -778,6 +807,7 @@ struct GattClient::WriteControlBlock final : public ProcedureControlBlock { { ble_error_t err = BLE_ERROR_UNSPECIFIED; offset += write_response.partial_value.size(); + tr_info("Prepared write partially complete offset=%d", offset); uint16_t data_left = write_length - offset; /* offset is guaranteed to be less of equal to write_length */ if (data_left) { uint16_t chunk_size = client->get_mtu(connection_handle) - PREPARE_WRITE_HEADER_LENGTH; @@ -798,6 +828,7 @@ struct GattClient::WriteControlBlock final : public ProcedureControlBlock { } if (err) { + tr_error("%s failed due to %s - clearing the queue", TRACE_CLASS, ble_error_to_string(err)); clear_prepare_queue(client, err, AttErrorResponse::UNLIKELY_ERROR); } } @@ -805,6 +836,7 @@ struct GattClient::WriteControlBlock final : public ProcedureControlBlock { void handle_execute_write_response(GattClient* client, const AttExecuteWriteResponse& execute_response) { if (prepare_success) { + tr_debug("Prepared write executed successfully"); status = BLE_ERROR_NONE; error_code = 0x00; } @@ -865,6 +897,8 @@ struct GattClient::WriteControlBlock final : public ProcedureControlBlock { break; } + tr_error("%s error: %s", TRACE_CLASS, attribute_error_code_to_string(error.error_code)); + if (error.request_opcode == AttributeOpcode(AttributeOpcode::PREPARE_WRITE_REQUEST)) { clear_prepare_queue(client, status, error.error_code); } else { @@ -892,7 +926,7 @@ struct GattClient::WriteControlBlock final : public ProcedureControlBlock { /* * Control block for the descriptor discovery process */ - +#define TRACE_CLASS "DescriptorDiscoveryControlBlock" struct GattClient::DescriptorDiscoveryControlBlock final : public ProcedureControlBlock { using ProcedureControlBlock::connection_handle; @@ -913,6 +947,8 @@ struct GattClient::DescriptorDiscoveryControlBlock final : public ProcedureContr ble_error_t start(GattClient *client) { + tr_info("Discover descriptor for char handle=%d", + characteristic.getDeclHandle()); return client->_pal_client.discover_characteristics_descriptors( connection_handle, attribute_handle_range( @@ -924,11 +960,13 @@ struct GattClient::DescriptorDiscoveryControlBlock final : public ProcedureContr void handle_timeout_error(GattClient *client) final { + tr_warning("%s timed out", TRACE_CLASS); terminate(client, BLE_ERROR_UNSPECIFIED); } void abort(GattClient *client) final { + tr_warning("%s aborted", TRACE_CLASS); terminate(client, BLE_ERROR_INVALID_STATE); } @@ -955,6 +993,7 @@ struct GattClient::DescriptorDiscoveryControlBlock final : public ProcedureContr void handle_error(GattClient *client, const AttErrorResponse &error) { + tr_error("%s error: %s", TRACE_CLASS, attribute_error_code_to_string(error.error_code)); if (error.error_code == AttErrorResponse::ATTRIBUTE_NOT_FOUND) { terminate(client, BLE_ERROR_NONE); } else { @@ -965,6 +1004,8 @@ struct GattClient::DescriptorDiscoveryControlBlock final : public ProcedureContr void handle_response(GattClient *client, const AttFindInformationResponse &response) { for (size_t i = 0; i < response.size(); ++i) { + tr_info("Discovered descriptor handle=%d uuid=%s for char handle=%d", + response[i].handle, to_string(response[i].uuid), characteristic.getDeclHandle()); DiscoveredCharacteristicDescriptor descriptor( &ble::BLE::Instance().gattClient(), connection_handle, response[i].handle, response[i].uuid ); @@ -993,6 +1034,10 @@ struct GattClient::DescriptorDiscoveryControlBlock final : public ProcedureContr void terminate(GattClient *client, ble_error_t status, uint8_t error_code = 0x00) { + if (status != BLE_ERROR_NONE) { + tr_warning("%s terminated due to %s %s", TRACE_CLASS, ble_error_to_string(status), attribute_error_code_to_string(error_code)); + } + client->remove_control_block(this); CharacteristicDescriptorDiscovery::TerminationCallbackParams_t params = { characteristic, @@ -1039,8 +1084,10 @@ ble_error_t GattClient::launchServiceDiscovery( const UUID &matching_characteristic_uuid ) { + tr_info("Launching service discovery (service: %s char: %s)", to_string(matching_service_uuid), to_string(matching_characteristic_uuid)); // verify that there is no other procedures going on this connection if (_is_reseting || get_control_block(connection_handle)) { + tr_error("cannot launch service discovery"); return BLE_ERROR_INVALID_STATE; } @@ -1059,6 +1106,7 @@ ble_error_t GattClient::launchServiceDiscovery( ); if (discovery_pcb == nullptr) { + tr_error("Failed to allocate DiscoveryControlBlock"); return BLE_ERROR_NO_MEM; } @@ -1082,6 +1130,7 @@ ble_error_t GattClient::launchServiceDiscovery( } if (err) { + tr_error("Discovery failed due to %s", ble_error_to_string(err)); remove_control_block(discovery_pcb); delete discovery_pcb; } @@ -1095,6 +1144,7 @@ ble_error_t GattClient::discoverServices( const UUID &matchingServiceUUID ) { + tr_info("Discover services with uuid=%s", to_string(matchingServiceUUID)); /* We take advantage of the property * that providing nullptr for the characteristic callback results in * characteristic discovery being skipped for each matching @@ -1112,6 +1162,7 @@ ble_error_t GattClient::discoverServices( GattAttribute::Handle_t endHandle ) { + tr_warning("discoverServices based on handle range not implemented"); return BLE_ERROR_NOT_IMPLEMENTED; } @@ -1132,6 +1183,7 @@ bool GattClient::isServiceDiscoveryActive() const void GattClient::terminateServiceDiscovery() { + tr_info("Terminate service discovery"); ProcedureControlBlock *pcb = control_blocks; while (pcb) { if (pcb->type == COMPLETE_DISCOVERY_PROCEDURE) { @@ -1150,6 +1202,7 @@ ble_error_t GattClient::read( { // verify that there is no other procedures going on this connection if (_is_reseting || get_control_block(connection_handle)) { + tr_error("cannot launch attribute read"); return BLE_ERROR_INVALID_STATE; } @@ -1160,6 +1213,7 @@ ble_error_t GattClient::read( ); if (read_pcb == nullptr) { + tr_error("Attribute read failed due to allocation error"); return BLE_ERROR_NO_MEM; } @@ -1167,6 +1221,8 @@ ble_error_t GattClient::read( ble_error_t err = BLE_ERROR_NONE; + tr_debug("Connection %d - read attribute %d offset %d", connection_handle, attribute_handle, offset); + if (offset == 0) { err = _pal_client.read_attribute_value( connection_handle, attribute_handle @@ -1178,6 +1234,7 @@ ble_error_t GattClient::read( } if (err) { + tr_error("Attribute read failed due %s", ble_error_to_string(err)); remove_control_block(read_pcb); delete read_pcb; } @@ -1195,9 +1252,12 @@ ble_error_t GattClient::write( ) const { if (_is_reseting || get_control_block(connection_handle)) { + tr_error("cannot launch attibute write"); return BLE_ERROR_INVALID_STATE; } + tr_debug("Connection %d - write attribute %d value %s", connection_handle, attribute_handle, tr_array(value, length)); + uint16_t mtu = get_mtu(connection_handle); #if BLE_FEATURE_SIGNING @@ -1218,6 +1278,7 @@ ble_error_t GattClient::write( #endif // BLE_FEATURE_SIGNING if (cmd == GATT_OP_WRITE_CMD) { if (length > (uint16_t) (mtu - WRITE_HEADER_LENGTH)) { + tr_error("Writes need to fit in a single message"); return BLE_ERROR_PARAM_OUT_OF_RANGE; } return _pal_client.write_without_response( @@ -1228,6 +1289,7 @@ ble_error_t GattClient::write( #if BLE_FEATURE_SIGNING } else if (cmd == GATT_OP_SIGNED_WRITE_CMD) { if (length > (uint16_t) (mtu - WRITE_HEADER_LENGTH - CMAC_LENGTH - MAC_COUNTER_LENGTH)) { + tr_error("Signed writes need to fit in single message"); return BLE_ERROR_PARAM_OUT_OF_RANGE; } ble_error_t status = _pal_client.signed_write_without_response( @@ -1247,6 +1309,7 @@ ble_error_t GattClient::write( if (length > (uint16_t) (mtu - WRITE_HEADER_LENGTH)) { data = (uint8_t *) malloc(length); if (data == nullptr) { + tr_err("Write failed due to allocation error"); return BLE_ERROR_NO_MEM; } memcpy(data, value, length); @@ -1261,6 +1324,7 @@ ble_error_t GattClient::write( if (write_pcb == nullptr) { free(data); + tr_err("Write failed due to allocation error"); return BLE_ERROR_NO_MEM; } @@ -1283,6 +1347,7 @@ ble_error_t GattClient::write( } if (err) { + tr_error("Write request failed due to %s", ble_error_to_string(err)); remove_control_block(write_pcb); delete write_pcb; } @@ -1298,6 +1363,7 @@ void GattClient::onServiceDiscoveryTermination( ServiceDiscovery::TerminationCallback_t callback ) { + tr_info("Service discovery ended"); _termination_callback = callback; } @@ -1308,6 +1374,8 @@ ble_error_t GattClient::discoverCharacteristicDescriptors( const CharacteristicDescriptorDiscovery::TerminationCallback_t &terminationCallback ) { + tr_info("Discover char descriptors %d", characteristic.getDeclHandle()); + // verify that there is no other procedures going on this connection if (_is_reseting || get_control_block(characteristic.getConnectionHandle())) { return BLE_ERROR_INVALID_STATE; @@ -1370,6 +1438,7 @@ void GattClient::terminateCharacteristicDescriptorDiscovery( const DiscoveredCharacteristic &characteristic ) { + tr_info("terminate char descriptor discovery %d", characteristic.getDeclHandle()); ProcedureControlBlock *pcb = control_blocks; while (pcb) { @@ -1397,6 +1466,7 @@ ble_error_t GattClient::negotiateAttMtu( ble_error_t GattClient::reset() { + tr_info("GattClient reset"); /* Notify that the instance is about to shut down. */ shutdownCallChain.call(&ble::BLE::Instance().gattClient()); shutdownCallChain.clear(); @@ -1434,6 +1504,7 @@ void GattClient::on_att_mtu_change( uint16_t att_mtu_size ) { + tr_info("MTU changed to %d", att_mtu_size); if (eventHandler) { eventHandler->onAttMtuChange(connection_handle, att_mtu_size); } @@ -1471,6 +1542,7 @@ void GattClient::on_server_message_received( const AttServerMessage &message ) { + tr_debug("Received server message %s", attribute_opcode_to_string(message.opcode)); switch (message.opcode) { case AttributeOpcode::ERROR_RESPONSE: case AttributeOpcode::EXCHANGE_MTU_RESPONSE: @@ -1493,6 +1565,7 @@ void GattClient::on_server_message_received( } break; default: + tr_warning("Unhandled message in gatt client received from server"); // invalid message receive return; } @@ -1527,6 +1600,7 @@ void GattClient::on_server_event(connection_handle_t connection, const AttServer callbacks_params.type = BLE_HVX_NOTIFICATION; callbacks_params.len = notification.attribute_value.size(); callbacks_params.data = notification.attribute_value.data(); + tr_debug("Notification for char: %d value: %s", notification.attribute_handle, tr_array(notification.attribute_value.data(), notification.attribute_value.size())); } break; case AttributeOpcode::HANDLE_VALUE_INDICATION: { @@ -1536,9 +1610,11 @@ void GattClient::on_server_event(connection_handle_t connection, const AttServer callbacks_params.type = BLE_HVX_INDICATION; callbacks_params.len = indication.attribute_value.size(); callbacks_params.data = indication.attribute_value.data(); + tr_debug("Indication for char: %d value: %s", indication.attribute_handle, tr_array(indication.attribute_value.data(), indication.attribute_value.size())); } break; default: + tr_warning("Unhandled event in gatt client received from server"); return; } @@ -1633,6 +1709,9 @@ uint16_t GattClient::get_mtu(connection_handle_t connection) const */ void GattClient::setEventHandler(EventHandler *handler) { + if (!handler) { + tr_warning("Setting a null gatt event handler"); + } eventHandler = handler; } @@ -1705,6 +1784,11 @@ GattClient::HVXCallbackChain_t &GattClient::onHVX() */ void GattClient::processReadResponse(const GattReadCallbackParams *params) { + if (params->status == BLE_ERROR_NONE) { + tr_debug("Att read complete handle 0x%x (offset %d), value %s", params->handle, params->offset, tr_array(params->data, params->len)); + } else { + tr_info("Connection %d - Att read failed with error %s", params->connHandle, ble_error_to_string(params->status)); + } onDataReadCallbackChain(params); } @@ -1713,6 +1797,11 @@ void GattClient::processReadResponse(const GattReadCallbackParams *params) */ void GattClient::processWriteResponse(const GattWriteCallbackParams *params) { + if (params->status == BLE_ERROR_NONE) { + tr_debug("Att write complete handle 0x%x", params->handle); + } else { + tr_info("Connection %d - Att write failed with error %s", params->connHandle, ble_error_to_string(params->status)); + } onDataWriteCallbackChain(params); }