Add traces to HCI, BLE instance, Security DB and WSF cordio traces (#14138)

* ble HCI tracing

* fix typo in SM trace

* add BLE instance tracing

* route wsf traces to mbed tr_debug

* Update connectivity/FEATURE_BLE/source/cordio/source/BLEInstanceBaseImpl.cpp

Co-authored-by: Vincent Coubard <[email protected]>

* print hci on cordio side

* trace controller supported features

* log reset sequence

* include config for printing enums

* remove duplicate trace

* add tracing to security db

* workaround for macro error on use outside trace

Co-authored-by: Vincent Coubard <[email protected]>

Author: paul-szczepanek-arm

connectivity/FEATURE_BLE/libraries/cordio_stack/wsf/include/wsf_trace.h

@@ -26,6 +26,10 @@
 
 #include <stdarg.h>
 
+#if MBED_CONF_CORDIO_TRACE_HCI_PACKETS
+#include "mbed_wsf_trace.h"
+#endif
+
 #ifdef __cplusplus
 extern "C" {
 #endif
@@ -289,6 +293,7 @@ bool_t WsfTokenService(void);
 /*! \brief 3 argument HCI error trace. */
 #define HCI_TRACE_ERR3(msg, var1, var2, var3)       WSF_TRACE3("HCI", "ERR",  msg, var1, var2, var3)
 
+#if !MBED_CONF_CORDIO_TRACE_HCI_PACKETS
 /*! \brief HCI PDUMP on command. */
 #define HCI_PDUMP_CMD(len, pBuf)
 /*! \brief HCI PDUMP on event. */
@@ -301,6 +306,7 @@ bool_t WsfTokenService(void);
 #define HCI_PDUMP_TX_ISO(len, pBuf)
 /*! \brief HCI PDUMP on Received ISO message. */
 #define HCI_PDUMP_RX_ISO(len, pBuf)
+#endif // !MBED_CONF_CORDIO_TRACE_HCI_PACKETS
 
 /*! \brief 0 argument DM info trace. */
 #define DM_TRACE_INFO0(msg)                         WSF_TRACE0("DM", "INFO", msg)

connectivity/FEATURE_BLE/mbed_lib.json

@@ -108,10 +108,15 @@
             "value": 16,
             "macro_name": "BLE_GAP_HOST_PRIVACY_RESOLVED_CACHE_SIZE"
         },
+
         "ble-passkey-display-reversed-digits-deprecation": {
           "help": "This option is part of the deprecation process. Set this to false to remove the deprecation notice. When set to true, the digits in the SecurityManager passkeyDiplay event are reversed. When set to false the digits are in the correct order.",
           "value": true,
           "macro_name": "BLE_PASSKEY_DISPLAY_REVERSED_DIGITS_DEPRECATION"
+        },
+        "trace-human-readable-enums": {
+            "help": "More hexadecimal values in traces will be printed as human readable strings.",
+            "value": false
         }
     },
     "target_overrides": {

connectivity/FEATURE_BLE/source/common/ble_trace_helpers.cpp

@@ -20,9 +20,23 @@
 
 #include "ble/SecurityManager.h"
 #include "mbed-trace/mbed_trace.h"
+#include "pal/GapTypes.h"
+#include "ble-host/include/dm_api.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* hci_opcode_to_string(uint16_t opcode);
+#endif //MBED_CONF_MBED_TRACE_ENABLE
+
+template<typename T>
+static inline const char* tr_as_array(T item)
+{
+    return (mbed_trace_array)((const uint8_t*)&item, sizeof(item));
+}
+
 static inline constexpr const char* to_string(bool v)
 {
     if (v) {

connectivity/FEATURE_BLE/source/common/ble_trace_helpers.h

@@ -29,4 +29,5 @@ target_sources(mbed-ble-cordio
         stack_adaptation/wsf_cs.c
         stack_adaptation/wsf_mbed_os_adaptation.c
         stack_adaptation/wsf_os.c
+        stack_adaptation/mbed_wsf_trace.c
 )

connectivity/FEATURE_BLE/source/cordio/CMakeLists.txt

@@ -27,6 +27,11 @@
 #include "bstream.h"
 #include "hci_mbed_os_adaptation.h"
 
+#include "mbed-trace/mbed_trace.h"
+#include "common/ble_trace_helpers.h"
+
+#define TRACE_GROUP "BLHC"
+
 #define HCI_RESET_RAND_CNT        4
 
 namespace ble {
@@ -69,12 +74,14 @@ CordioHCIDriver::CordioHCIDriver(CordioHCITransportDriver& transport_driver) :
 
 void CordioHCIDriver::initialize()
 {
+    tr_info("CordioHCIDriver initializing");
     _transport_driver.initialize();
     do_initialize();
 }
 
 void CordioHCIDriver::terminate()
 {
+    tr_info("CordioHCIDriver terminating");
     do_terminate();
     _transport_driver.terminate();
 }
@@ -275,19 +282,34 @@ bool CordioHCIDriver::get_random_static_address(ble::address_t& address)
 
 void CordioHCIDriver::signal_reset_sequence_done()
 {
+    tr_debug("Signal cordio HCI reset sequence done");
     hci_mbed_os_signal_reset_sequence_done();
 }
 
 uint16_t CordioHCIDriver::write(uint8_t type, uint16_t len, uint8_t *pData)
 {
+#if MBED_CONF_CORDIO_TRACE_HCI_PACKETS
+    const char *type_prefix;
+    switch(type) {
+        case 0x01: type_prefix = "CMD"; break;
+        case 0x02: type_prefix = "ACL"; break;
+        /* illegal packet */
+        default: type_prefix = "ERR"; break;
+    }
+    tr_debug("HOST->LL %s %s", type_prefix, trace_array(pData, len));
+#endif
     return _transport_driver.write(type, len, pData);
 }
 
 void CordioHCIDriver::on_host_stack_inactivity()
 {
 }
+
 void CordioHCIDriver::handle_test_end(bool success, uint16_t packets)
 {
+    MBED_ASSERT(_test_end_handler);
+    tr_info("LE receiver mode ended (success: %s)", to_string(success));
+
     if (_test_end_handler) {
         _test_end_handler(success, packets);
         _test_end_handler = nullptr;
@@ -299,17 +321,21 @@ ble_error_t CordioHCIDriver::rf_test_start_le_receiver_test(
 )
 {
     if (_test_end_handler) {
+        tr_warning("Cannot start LE %s test mode - already started", "receiver");
         return BLE_ERROR_INVALID_STATE;
     }
 
     if (!test_end_handler) {
+        tr_warning("Cannot start LE %s  test mode - invalid handler", "receiver");
         return BLE_ERROR_INVALID_PARAM;
     }
 
     _test_end_handler = test_end_handler;
     uint8_t *buf = hciCmdAlloc(HCI_OPCODE_LE_RECEIVER_TEST, HCI_LEN_LE_RECEIVER_TEST);
 
     if (buf) {
+        tr_info("LE %s mode starter on channel %hhd", "receiver", channel);
+
         uint8_t* p = buf + HCI_CMD_HDR_LEN;
         UINT8_TO_BSTREAM(p, channel);
         hciCmdSend(buf);
@@ -325,17 +351,21 @@ ble_error_t CordioHCIDriver::rf_test_start_le_transmitter_test(
 )
 {
     if (_test_end_handler) {
+        tr_warning("Cannot start LE %s test mode - already started", "transmitter");
         return BLE_ERROR_INVALID_STATE;
     }
 
     if (!test_end_handler) {
+        tr_warning("Cannot start LE %s  test mode - invalid handler", "transmitter");
         return BLE_ERROR_INVALID_PARAM;
     }
 
     _test_end_handler = test_end_handler;
     uint8_t *buf = hciCmdAlloc(HCI_OPCODE_LE_TRANSMITTER_TEST, HCI_LEN_LE_TRANSMITTER_TEST);
 
     if (buf) {
+        tr_info("LE %s mode starter on channel %hhd", "transmitter", channel);
+
         uint8_t* p = buf + HCI_CMD_HDR_LEN;
         UINT8_TO_BSTREAM(p, channel);
         UINT8_TO_BSTREAM(p, length);
@@ -350,14 +380,18 @@ ble_error_t CordioHCIDriver::rf_test_start_le_transmitter_test(
 
 ble_error_t CordioHCIDriver::rf_test_end()
 {
+    MBED_ASSERT(_test_end_handler);
+
     if (!_test_end_handler) {
+        tr_info("Cannot end LE transmitter mode test - missing handler (test never started?)");
         return BLE_ERROR_INVALID_STATE;
     }
 
     uint8_t *buf = hciCmdAlloc(HCI_OPCODE_LE_TEST_END, HCI_LEN_LE_TEST_END);
 
     if (buf) {
         hciCmdSend(buf);
+        tr_info("LE transmitter mode ended");
 
         return BLE_ERROR_NONE;
     }

connectivity/FEATURE_BLE/source/cordio/driver/CordioHCIDriver.cpp

@@ -21,6 +21,11 @@
 #include "ble/driver/CordioHCITransportDriver.h"
 #include "ble/driver/CordioHCIDriver.h"
 
+#include "mbed-trace/mbed_trace.h"
+#include "common/ble_trace_helpers.h"
+
+#define TRACE_GROUP "BLHC"
+
 extern "C" void hciTrSerialRxIncoming(uint8_t *pBuf, uint8_t len);
 
 namespace ble {
@@ -40,6 +45,7 @@ void CordioHCITransportDriver::on_data_received(uint8_t* data, uint16_t len)
 
 void CordioHCITransportDriver::set_data_received_handler(data_received_handler_t handler)
 {
+    MBED_ASSERT(handler);
     data_received_handler = handler;
 }
 

connectivity/FEATURE_BLE/source/cordio/driver/CordioHCITransportDriver.cpp

@@ -81,6 +81,15 @@
             "help": "Check connection complete event if it needs the addresses swapped due to bug in controller",
             "value": null,
             "macro_name": "CORDIO_RPA_SWAP_WORKAROUND"
+        },
+        "trace-hci-packets": {
+            "help": "If tracing is enabled at level DEBUG traces will include HCI packet traces.",
+            "value": false
+        },
+        "trace-cordio-wsf-traces": {
+            "help": "If tracing is enabled at level DEBUG traces will include WSF traces from Cordio packet traces.",
+            "value": false,
+            "macro_name": "WSF_TRACE_ENABLED"
         }
     },
     "target_overrides": {