BLE: Add privacy trace (#14127)

Add traces to the Bluetooth Security Manager and Privacy controller.
The traces are made to be comprehensive to improve the ux when users submit bugs.
A centralized set of helpers has been created to convert BLE types to string.

* BLE: Add SM traces

* BLE: Add traces to Security Manager PAL

* BLE: Make SM traces consistent.
- Prefix with Connection <id> - when appropriate.
- Display parameters after `:`.
- If multiple parameters should be displayed name then and print the value after =. They are separated by a `,`.

* BLE: Fix SM random number generation.

Only the first 8 bytes were generated from the stack.

* BLE: Regenerate CSRK if it is all zeroes.

* BLE: Add trace into privacy modules

Address resolution is set at the debug level as it is a very common operation and may clutter the output.

* Address trace review for SM:

- Put privacy traces in BLPR
- Add missing traces in PALSecurityManagerImpl.cpp
- Add missing EventHandler null pointer check
- Typo and parameters order fix.

connectivity/FEATURE_BLE/source/common/ble_trace_helpers.h

@@ -0,0 +1,206 @@
+/* mbed Microcontroller Library
+ * Copyright (c) 2021 ARM Limited
+ * SPDX-License-Identifier: Apache-2.0
+ * 
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#ifndef BLE_CLIAPP_BLE_TRACE_HELPERS_H
+#define BLE_CLIAPP_BLE_TRACE_HELPERS_H
+
+#include "ble/SecurityManager.h"
+#include "mbed-trace/mbed_trace.h"
+
+namespace ble {
+
+static inline constexpr const char* to_string(bool v)
+{
+    if (v) {
+        return "true";
+    } else {
+        return "false";
+    }
+}
+
+static inline constexpr const char* to_string(ble::SecurityManager::SecurityIOCapabilities_t capabilities)
+{
+    switch(capabilities) {
+        case ble::SecurityManager::IO_CAPS_DISPLAY_ONLY:
+            return "IO_CAPS_DISPLAY_ONLY";
+        case ble::SecurityManager::IO_CAPS_DISPLAY_YESNO:
+            return "IO_CAPS_DISPLAY_YESNO";
+        case ble::SecurityManager::IO_CAPS_KEYBOARD_DISPLAY:
+            return "IO_CAPS_KEYBOARD_DISPLAY";
+        case ble::SecurityManager::IO_CAPS_KEYBOARD_ONLY:
+            return "IO_CAPS_KEYBOARD_ONLY";
+        case ble::SecurityManager::IO_CAPS_NONE:
+            return "IO_CAPS_NONE";
+        default:
+            return "unknown";
+    }
+}
+
+static inline const char* to_string(ble::io_capability_t capabilities)
+{
+    switch (capabilities.value()) {
+        case ble::io_capability_t::DISPLAY_ONLY:
+            return "DISPLAY_ONLY";
+        case ble::io_capability_t::DISPLAY_YES_NO:
+            return "IO_CAPS_DISPLAY_DISPLAY_YES_NOYESNO";
+        case ble::io_capability_t::KEYBOARD_ONLY:
+            return "KEYBOARD_ONLY";
+        case ble::io_capability_t::NO_INPUT_NO_OUTPUT:
+            return "NO_INPUT_NO_OUTPUT";
+        case ble::io_capability_t::KEYBOARD_DISPLAY:
+            return "KEYBOARD_DISPLAY";
+        default:
+            return "unknown";
+    }
+}
+
+static inline constexpr const char* to_string(ble::SecurityManager::SecurityMode_t security_mode)
+{
+    switch (security_mode) {
+        case ble::SecurityManager::SECURITY_MODE_NO_ACCESS:
+            return "SECURITY_MODE_NO_ACCESS";
+        case ble::SecurityManager::SECURITY_MODE_ENCRYPTION_OPEN_LINK:
+            return "SECURITY_MODE_ENCRYPTION_OPEN_LINK";
+        case ble::SecurityManager::SECURITY_MODE_ENCRYPTION_NO_MITM:
+            return "SECURITY_MODE_ENCRYPTION_NO_MITM";
+        case ble::SecurityManager::SECURITY_MODE_ENCRYPTION_WITH_MITM:
+            return "SECURITY_MODE_ENCRYPTION_WITH_MITM";
+        case ble::SecurityManager::SECURITY_MODE_SIGNED_NO_MITM:
+            return "SECURITY_MODE_SIGNED_NO_MITM";
+        case ble::SecurityManager::SECURITY_MODE_SIGNED_WITH_MITM:
+            return "SECURITY_MODE_SIGNED_WITH_MITM";
+        default:
+            return "Unknown";
+    }
+}
+
+static inline constexpr const char* passkey_str(const uint8_t* passkey)
+{
+    if (!passkey) {
+        return "0";
+    } else {
+        return (mbed_trace_array)(passkey, 6);
+    }
+}
+
+static inline const char* to_string(const ble::address_t& address)
+{
+    return (mbed_trace_array)(address.data(), address.size());
+}
+
+template<size_t size>
+const char* to_string(const ble::byte_array_t<size> &array)
+{
+    return (mbed_trace_array)(array.data(), array.size());
+}
+
+static inline const char* to_string(const ble::link_encryption_t encryption)
+{
+    using link_encryption_t = ble::link_encryption_t;
+
+    switch (encryption.value()) {
+        case link_encryption_t::NOT_ENCRYPTED:
+            return "NOT_ENCRYPTED";
+        case link_encryption_t::ENCRYPTION_IN_PROGRESS:
+            return "ENCRYPTION_IN_PROGRESS";
+        case link_encryption_t::ENCRYPTED:
+            return "ENCRYPTED";
+        case link_encryption_t::ENCRYPTED_WITH_MITM:
+            return "ENCRYPTED_WITH_MITM";
+        case link_encryption_t::ENCRYPTED_WITH_SC_AND_MITM:
+            return "ENCRYPTED_WITH_SC_AND_MITM";
+        default:
+            return "Unknown";
+    }
+}
+
+static inline const char* to_string(Keypress_t keypress)
+{
+    switch (keypress) {
+        case KEYPRESS_STARTED:
+            return "KEYPRESS_STARTED";
+        case KEYPRESS_ENTERED:
+            return "KEYPRESS_ENTERED";
+        case KEYPRESS_ERASED:
+            return "KEYPRESS_ERASED";
+        case KEYPRESS_CLEARED:
+            return "KEYPRESS_CLEARED";
+        case KEYPRESS_COMPLETED:
+            return "KEYPRESS_COMPLETED";
+        default:
+            return "Unknown";
+    }
+}
+
+static inline const char *to_string(ble::pairing_failure_t reason)
+{
+    switch (reason.value()) {
+        case ble::pairing_failure_t::PASSKEY_ENTRY_FAILED:
+            return "PASSKEY_ENTRY_FAILED";
+        case ble::pairing_failure_t::OOB_NOT_AVAILABLE:
+            return "OOB_NOT_AVAILABLE";
+        case ble::pairing_failure_t::AUTHENTICATION_REQUIREMENTS:
+            return "AUTHENTICATION_REQUIREMENTS";
+        case ble::pairing_failure_t::CONFIRM_VALUE_FAILED:
+            return "CONFIRM_VALUE_FAILED";
+        case ble::pairing_failure_t::PAIRING_NOT_SUPPORTED:
+            return "PAIRING_NOT_SUPPORTED";
+        case ble::pairing_failure_t::ENCRYPTION_KEY_SIZE:
+            return "ENCRYPTION_KEY_SIZE";
+        case ble::pairing_failure_t::COMMAND_NOT_SUPPORTED:
+            return "COMMAND_NOT_SUPPORTED";
+        case ble::pairing_failure_t::UNSPECIFIED_REASON:
+            return "UNSPECIFIED_REASON";
+        case ble::pairing_failure_t::REPEATED_ATTEMPTS:
+            return "REPEATED_ATTEMPTS";
+        case ble::pairing_failure_t::INVALID_PARAMETERS:
+            return "INVALID_PARAMETERS";
+        case ble::pairing_failure_t::DHKEY_CHECK_FAILED:
+            return "DHKEY_CHECK_FAILED";
+        case ble::pairing_failure_t::NUMERIC_COMPARISON_FAILED:
+            return "NUMERIC_COMPARISON_FAILED";
+        case ble::pairing_failure_t::BR_EDR_PAIRING_IN_PROGRESS:
+            return "BR_EDR_PAIRING_IN_PROGRESS";
+        case ble::pairing_failure_t::CROSS_TRANSPORT_KEY_DERIVATION_OR_GENERATION_NOT_ALLOWED:
+            return "CROSS_TRANSPORT_KEY_DERIVATION_OR_GENERATION_NOT_ALLOWED";
+        default:
+            return "Unknown";
+    }
+}
+
+static inline const char *to_string(target_peer_address_type_t type)
+{
+    if (type == target_peer_address_type_t::PUBLIC) {
+        return "PUBLIC";
+    } else {
+        return "RANDOM";
+    }
+}
+
+static inline const char *to_string(privacy_mode_t mode)
+{
+    if (mode == privacy_mode_t::NETWORK) {
+        return "NETWORK";
+    } else {
+        return "DEVICE";
+    }
+}
+
+
+} // namespace ble
+
+#endif //BLE_CLIAPP_BLE_TRACE_HELPERS_H

connectivity/FEATURE_BLE/source/cordio/source/PalPrivateAddressControllerImpl.cpp

@@ -19,24 +19,32 @@
 
 #include "PalPrivateAddressControllerImpl.h"
 #include "dm_api.h"
+#include "mbed-trace/mbed_trace.h"
+#include "common/ble_trace_helpers.h"
+
+#define TRACE_GROUP "BLPR"
 
 namespace ble {
 namespace impl {
 
 ble_error_t PalPrivateAddressController::initialize()
 {
+    tr_info("Initialize privacy PAL");
     DmPrivInit();
     return BLE_ERROR_NONE;
 }
 
 ble_error_t PalPrivateAddressController::terminate()
 {
+    tr_info("Terminate privacy PAL");
     return BLE_ERROR_NONE;
 }
 
 ble_error_t PalPrivateAddressController::generate_resolvable_private_address(const irk_t& local_irk)
 {
+    tr_info("PAL start generation of RPA from local irk: %s", to_string(local_irk));
     if (_generating_rpa) {
+        tr_error("PAL can't generate RPA, it is busy handling a previous request");
         return BLE_ERROR_INVALID_STATE;
     }
 
@@ -50,6 +58,7 @@ address_t PalPrivateAddressController::generate_non_resolvable_private_address()
     address_t address;
     SecRand(address.data(), address.size());
     DM_RAND_ADDR_SET(address, DM_RAND_ADDR_NONRESOLV);
+    tr_info("Non resolvable private address generated: %s", to_string(address));
     return address;
 }
 
@@ -59,9 +68,11 @@ ble_error_t PalPrivateAddressController::resolve_private_address(
 )
 {
     if (_resolving_rpa) {
+        tr_error("Failed to start resolution of RPA: Handling a previous request");
         return BLE_ERROR_INVALID_STATE;
     }
 
+    tr_debug("Start resolution of private address: address=%s, irk=%s", to_string(address), to_string(irk));
     DmPrivResolveAddr(
         const_cast<uint8_t*>(address.data()),
         const_cast<uint8_t*>(irk.data()),
@@ -77,6 +88,7 @@ bool PalPrivateAddressController::is_ll_privacy_supported()
 
 ble_error_t PalPrivateAddressController::set_ll_address_resolution(bool enable)
 {
+    tr_info("Enable LL private address resolution");
     DmPrivSetAddrResEnable(enable);
     return BLE_ERROR_NONE;
 }
@@ -86,9 +98,11 @@ ble_error_t PalPrivateAddressController::set_ll_resolvable_private_address_timeo
 )
 {
     if (HciLlPrivacySupported() == false) {
+        tr_error("Operation not supported by LL: RPA generation");
         return BLE_ERROR_NOT_IMPLEMENTED;
     }
 
+    tr_info("Set LL resolvable private address generation timeout: %d s", timeout.value());
     DmPrivSetResolvablePrivateAddrTimeout(timeout.value());
     return BLE_ERROR_NONE;
 }
@@ -106,8 +120,12 @@ ble_error_t PalPrivateAddressController::add_device_to_resolving_list(
 )
 {
     if (is_ll_privacy_supported() == false) {
+        tr_error("Operation not supported by LL: RPA resolution");
         return BLE_ERROR_NOT_IMPLEMENTED;
     }
+
+    tr_info("Add RPA to LL resolving list: peer address=%s, type=%s, peer irk=%s, local irk=%s",
+        to_string(peer_identity_address), to_string(peer_address_type), to_string(peer_irk), to_string(local_irk));
     DmPrivAddDevToResList(
         peer_address_type.value(),
         peer_identity_address.data(),
@@ -130,9 +148,12 @@ ble_error_t PalPrivateAddressController::remove_device_from_resolving_list(
 )
 {
     if (is_ll_privacy_supported() == false) {
+        tr_error("Operation not supported by LL: RPA resolution");
         return BLE_ERROR_NOT_IMPLEMENTED;
     }
 
+    tr_info("Remove RPA from LL resolving list: peer address=%s, type=%s",
+        to_string(peer_identity_address), to_string(peer_address_type));
     DmPrivRemDevFromResList(peer_address_type.value(), peer_identity_address.data(), 0);
     return BLE_ERROR_NONE;
 }
@@ -144,8 +165,11 @@ ble_error_t PalPrivateAddressController::set_peer_privacy_mode(
 )
 {
     if (is_ll_privacy_supported() == false) {
+        tr_error("Operation not supported by LL: privacy");
         return BLE_ERROR_NOT_IMPLEMENTED;
     }
+    tr_info("Set privacy mode: peer address=%s, type=%s, mode=%s",
+        to_string(peer_address), to_string(peer_address_type), to_string(privacy_mode));
     DmPrivSetPrivacyMode(
         peer_address_type.value(),
         peer_address.data(),
@@ -157,9 +181,11 @@ ble_error_t PalPrivateAddressController::set_peer_privacy_mode(
 ble_error_t PalPrivateAddressController::clear_resolving_list()
 {
     if (is_ll_privacy_supported() == false) {
+        tr_error("Operation not supported by LL: privacy resolving list");
         return BLE_ERROR_NOT_IMPLEMENTED;
     }
 
+    tr_info("Clear LL resolving list");
     DmPrivClearResList();
     return BLE_ERROR_NONE;
 }
@@ -178,6 +204,7 @@ PalPrivateAddressController& PalPrivateAddressController::instance()
 bool PalPrivateAddressController::cordio_handler(const wsfMsgHdr_t *msg)
 {
     if (msg == nullptr) {
+        tr_warning("Privacy handler received null message");
         return false;
     }
 
@@ -185,9 +212,11 @@ bool PalPrivateAddressController::cordio_handler(const wsfMsgHdr_t *msg)
 
     switch (msg->event) {
         case DM_PRIV_GENERATE_ADDR_IND: {
+            tr_info("Privacy handling: DM_PRIV_GENERATE_ADDR_IND");
             instance()._generating_rpa = false;
 
             if (!handler) {
+                tr_warning("No user handler registered for PAL privacy");
                 return true;
             }
 
@@ -217,7 +246,15 @@ bool PalPrivateAddressController::cordio_handler(const wsfMsgHdr_t *msg)
         case DM_PRIV_REM_DEV_FROM_RES_LIST_IND: // Device removed from resolving list
         case DM_PRIV_CLEAR_RES_LIST_IND: // Resolving list cleared
         {
+            tr_info("Privacy handling: %s",
+                msg->event == DM_PRIV_ADD_DEV_TO_RES_LIST_IND ?
+                    "DM_PRIV_ADD_DEV_TO_RES_LIST_IND" :
+                    msg->event == DM_PRIV_ADD_DEV_TO_RES_LIST_IND ?
+                        "DM_PRIV_REM_DEV_FROM_RES_LIST_IND" :
+                        "DM_PRIV_CLEAR_RES_LIST_IND"
+            );
             if (!handler) {
+                tr_warning("No user handler registered for PAL privacy");
                 return true;
             }
 

connectivity/FEATURE_BLE/source/cordio/source/PalSecurityManagerImpl.cpp

@@ -30,6 +30,11 @@
 #include "wsf_os.h"
 #include "hci_core.h"
 
+#include "mbed-trace/mbed_trace.h"
+#include "common/ble_trace_helpers.h"
+
+#define TRACE_GROUP "BLSM"
+
 namespace ble {
 namespace impl {
 
@@ -51,6 +56,7 @@ PalSecurityManager::~PalSecurityManager()
 
 ble_error_t PalSecurityManager::initialize()
 {
+    tr_info("Initialize PAL SM");
     // reset local state
     _use_default_passkey = false;
     _default_passkey = 0;
@@ -73,6 +79,7 @@ ble_error_t PalSecurityManager::initialize()
 
 ble_error_t PalSecurityManager::terminate()
 {
+    tr_info("Terminate PAL SM");
 #if BLE_FEATURE_SIGNING
     cleanup_peer_csrks();
 #endif // BLE_FEATURE_SIGNING
@@ -82,6 +89,7 @@ ble_error_t PalSecurityManager::terminate()
 
 ble_error_t PalSecurityManager::reset()
 {
+    tr_info("Reset PAL SM");
 #if BLE_FEATURE_SIGNING
     cleanup_peer_csrks();
 #endif // BLE_FEATURE_SIGNING
@@ -134,6 +142,7 @@ ble_error_t PalSecurityManager::set_authentication_timeout(
     connection_handle_t connection, uint16_t timeout_in_10ms
 )
 {
+    tr_info("Connection %d - pass authentication timeout %d to the stack", connection, timeout_in_10ms);
     DmWriteAuthPayloadTimeout(connection, timeout_in_10ms);
     return BLE_ERROR_NONE;
 }
@@ -153,6 +162,7 @@ ble_error_t PalSecurityManager::slave_security_request(
     AuthenticationMask authentication
 )
 {
+    tr_info("Connection %d - Pass slave security to the stack: authentication = %02x", connection, authentication.value());
     DmSecSlaveReq(connection, authentication.value());
     return BLE_ERROR_NONE;
 }
@@ -171,6 +181,8 @@ ble_error_t PalSecurityManager::enable_encryption(
     bool mitm
 )
 {
+    tr_info("Connection %d - Enable encryption: lth = %s, rand = %s, ediv = %s, mitm = %s",
+        connection, to_string(ltk), to_string(rand), to_string(ediv), to_string(mitm));
     dmSecLtk_t sec_ltk;
     memcpy(sec_ltk.key, ltk.data(), ltk.size());
     memcpy(sec_ltk.rand, rand.data(), rand.size());
@@ -192,6 +204,8 @@ ble_error_t PalSecurityManager::enable_encryption(
     bool mitm
 )
 {
+    tr_info("Connection %d - Enable SC encryption: ltk = %s, mitm = %s",
+        connection, to_string(ltk), to_string(mitm));
     dmSecLtk_t sec_ltk = {0};
     memcpy(sec_ltk.key, ltk.data(), ltk.size());
 
@@ -213,6 +227,7 @@ ble_error_t PalSecurityManager::encrypt_data(
     encryption_block_t &data
 )
 {
+    tr_warning("PAL Encrypt data not implemented");
     return BLE_ERROR_NOT_IMPLEMENTED;
 }
 
@@ -229,6 +244,8 @@ ble_error_t PalSecurityManager::set_ltk(
     bool secure_connections
 )
 {
+    tr_info("Connection %d - send ltk response: ltk = %s, mitm = %s, sc = %s ",
+        connection, to_string(ltk), to_string(mitm), to_string(secure_connections));
     uint8_t security_level = DM_SEC_LEVEL_NONE;
     if (secure_connections) {
         security_level = DM_SEC_LEVEL_ENC_LESC;
@@ -252,6 +269,7 @@ ble_error_t PalSecurityManager::set_ltk_not_found(
     connection_handle_t connection
 )
 {
+    tr_info("Connection %d - Reply LTK not found", connection);
     DmSecLtkRsp(
         connection,
         /* key found */ false,
@@ -265,6 +283,7 @@ ble_error_t PalSecurityManager::set_ltk_not_found(
 
 ble_error_t PalSecurityManager::set_irk(const irk_t &irk)
 {
+    tr_info("Set stack local IRK: %s", to_string(irk));
     _irk = irk;
     DmSecSetLocalIrk(_irk.data());
     return BLE_ERROR_NONE;
@@ -275,6 +294,7 @@ ble_error_t PalSecurityManager::set_identity_address(
     bool public_address
 )
 {
+    tr_info("Set stack local identity address: address = %s, public = %s", to_string(address), to_string(public_address));
     DmSecSetLocalIdentityAddr(
         address.data(),
         public_address ? DM_ADDR_PUBLIC : DM_ADDR_RANDOM
@@ -288,6 +308,7 @@ ble_error_t PalSecurityManager::set_csrk(
     sign_count_t sign_counter
 )
 {
+    tr_info("Set stack local CSRK: CSRK = %s, sign counter = %" PRIu32, to_string(csrk), sign_counter);
     _csrk = csrk;
     DmSecSetLocalCsrk(_csrk.data());
 #if BLE_FEATURE_GATT_CLIENT
@@ -307,9 +328,13 @@ ble_error_t PalSecurityManager::set_peer_csrk(
 )
 {
     if (connection == 0 || connection > DM_CONN_MAX) {
+        tr_error("Connection %d - Imposible to set stack peer CSRK, invalid connection ID", connection);
         return BLE_ERROR_INVALID_PARAM;
     }
 
+    tr_info("Connection %d - Set stack peer CSRK: CSRK = %s, authenticated = %s, sign_counter = %" PRIu32,
+        connection, to_string(csrk), to_string(authenticated), sign_counter);
+
     size_t connection_index = connection - 1;
 
     if (_peer_csrks[connection_index]) {
@@ -330,9 +355,12 @@ ble_error_t PalSecurityManager::set_peer_csrk(
 ble_error_t PalSecurityManager::remove_peer_csrk(connection_handle_t connection)
 {
     if (connection == 0 || connection > DM_CONN_MAX) {
+        tr_error("Connection %d - Imposible to set stack peer CSRK, invalid connection ID", connection);
         return BLE_ERROR_INVALID_PARAM;
     }
 
+    tr_info("Connection %d - Remove stack peer CSRK", connection);
+
     size_t connection_index = connection - 1;
 
     if (_peer_csrks[connection_index]) {
@@ -352,6 +380,9 @@ ble_error_t PalSecurityManager::remove_peer_csrk(connection_handle_t connection)
 
 ble_error_t PalSecurityManager::set_display_passkey(passkey_num_t passkey)
 {
+    PasskeyAscii ascii_passkey(passkey);
+    tr_info("Set stack display passkey: %s", passkey_str(ascii_passkey.value()));
+
     if (passkey) {
         _use_default_passkey = true;
         _default_passkey = passkey;
@@ -364,6 +395,7 @@ ble_error_t PalSecurityManager::set_display_passkey(passkey_num_t passkey)
 
 ble_error_t PalSecurityManager::set_io_capability(io_capability_t io_capability)
 {
+    tr_info("Set stack I/O capabilities: %s", to_string(io_capability));
     pSmpCfg->ioCap = io_capability.value();
     return BLE_ERROR_NONE;
 }
@@ -374,6 +406,7 @@ ble_error_t PalSecurityManager::set_encryption_key_requirements(
     uint8_t max_encryption_key_size
 )
 {
+    tr_info("Set stack encryption key requirements: [%d : %d]", min_encryption_key_size, max_encryption_key_size);
     if ((min_encryption_key_size < 7) || (min_encryption_key_size > 16) ||
         (min_encryption_key_size > max_encryption_key_size)) {
         return BLE_ERROR_INVALID_PARAM;
@@ -398,6 +431,8 @@ ble_error_t PalSecurityManager::send_pairing_request(
     KeyDistribution responder_dist
 )
 {
+    tr_info("Connection %d - send pairing request: oob = %s, auth = %02X, initiator dist = %02x, responder dist = %02X",
+        connection, to_string(oob_data_flag), authentication_requirements.value(), initiator_dist.value(), responder_dist.value());
     DmSecPairReq(
         connection,
         oob_data_flag,
@@ -419,6 +454,8 @@ ble_error_t PalSecurityManager::send_pairing_response(
     KeyDistribution responder_dist
 )
 {
+    tr_info("Connection %d - Send pairing response: oob = %s, auth = %02X, initiator dist = %02x, responder dist = %02X",
+        connection, to_string(oob_data_flag), authentication_requirements.value(), initiator_dist.value(), responder_dist.value());
     DmSecPairRsp(
         connection,
         oob_data_flag,
@@ -436,6 +473,7 @@ ble_error_t PalSecurityManager::cancel_pairing(
     connection_handle_t connection, pairing_failure_t reason
 )
 {
+    tr_info("Connection %d - cancel pairing: reason = %s", connection, to_string(reason));
     DmSecCancelReq(connection, reason.value());
     return BLE_ERROR_NONE;
 }
@@ -444,6 +482,7 @@ ble_error_t PalSecurityManager::cancel_pairing(
 ble_error_t PalSecurityManager::get_random_data(byte_array_t<8> &random_data)
 {
     SecRand(random_data.data(), random_data.size());
+    tr_info("Stack generated random data: %s", to_string(random_data));
     return BLE_ERROR_NONE;
 }
 
@@ -456,6 +495,7 @@ ble_error_t PalSecurityManager::passkey_request_reply(
     connection_handle_t connection, passkey_num_t passkey
 )
 {
+    tr_info("Connection %d - Reply with passkey %s", connection, passkey_str(PasskeyAscii(passkey).value()));
     DmSecAuthRsp(
         connection,
         /* datalength */ 3,
@@ -471,6 +511,7 @@ ble_error_t PalSecurityManager::legacy_pairing_oob_request_reply(
     const oob_tk_t &oob_data
 )
 {
+    tr_info("Connection %d - Reply with legacy OOB data %s", connection, to_string(oob_data));
     DmSecAuthRsp(
         connection,
         /* data length */16,
@@ -485,6 +526,7 @@ ble_error_t PalSecurityManager::confirmation_entered(
     connection_handle_t connection, bool confirmation
 )
 {
+    tr_info("Connection %d - Send confirmation entered: %s", connection, to_string(confirmation));
     DmSecCompareRsp(connection, confirmation);
     return BLE_ERROR_NONE;
 }
@@ -497,6 +539,7 @@ ble_error_t PalSecurityManager::send_keypress_notification(
     connection_handle_t connection, ble::Keypress_t keypress
 )
 {
+    tr_info("Connection %d - Send keypress notification: %s", connection, to_string(keypress));
     DmSecKeypressReq(connection, keypress);
     return BLE_ERROR_NONE;
 }
@@ -504,6 +547,7 @@ ble_error_t PalSecurityManager::send_keypress_notification(
 
 ble_error_t PalSecurityManager::generate_secure_connections_oob()
 {
+    tr_info("Start generation of SC OOB");
     uint8_t oobLocalRandom[SMP_RAND_LEN];
     SecRand(oobLocalRandom, SMP_RAND_LEN);
     DmSecCalcOobReq(oobLocalRandom, _public_key_x);
@@ -518,6 +562,8 @@ ble_error_t PalSecurityManager::secure_connections_oob_request_reply(
     const oob_confirm_t &peer_confirm
 )
 {
+    tr_info("Connection %d - Reply to SC OOB request: local_random = %s, peer_random = %s, peer_confirm = %s",
+        connection, to_string(local_random), to_string(peer_random), to_string(peer_confirm));
     dmSecLescOobCfg_t oob_config = {0};
 
     memcpy(oob_config.localRandom, local_random.data(), local_random.size());
@@ -547,11 +593,13 @@ bool PalSecurityManager::sm_handler(const wsfMsgHdr_t *msg)
     PalSecurityManagerEventHandler *handler = self.get_event_handler();
 
     if ((msg == nullptr) || (handler == nullptr)) {
+        tr_warning("PAL Event handler: invalid message (%p) or handler (%p)", msg, handler);
         return false;
     }
 
     switch (msg->event) {
         case DM_SEC_PAIR_CMPL_IND: {
+            tr_info("Handling event DM_SEC_PAIR_CMPL_IND");
             auto *evt = (dmSecPairCmplIndEvt_t *) msg;
             // Note: authentication and bonding flags present in the auth field
             handler->on_pairing_completed(evt->hdr.param);
@@ -559,6 +607,7 @@ bool PalSecurityManager::sm_handler(const wsfMsgHdr_t *msg)
         }
 
         case DM_SEC_PAIR_FAIL_IND: {
+            tr_info("Handling event DM_SEC_PAIR_FAIL_IND");
             connection_handle_t connection = msg->param;
             uint8_t status = msg->status;
 
@@ -587,6 +636,7 @@ bool PalSecurityManager::sm_handler(const wsfMsgHdr_t *msg)
         }
 
         case DM_SEC_ENCRYPT_IND: {
+            tr_info("Handling event DM_SEC_ENCRYPT_IND");
             auto *evt = (dmSecEncryptIndEvt_t *) msg;
             // note: the field usingLtk of the message indicates if an LTK was
             // used to encrypt the link
@@ -596,12 +646,14 @@ bool PalSecurityManager::sm_handler(const wsfMsgHdr_t *msg)
         }
 
         case DM_SEC_ENCRYPT_FAIL_IND: {
+            tr_info("Handling event DM_SEC_ENCRYPT_FAIL_IND");
             // note: msg->status contains the encryption failure status
             handler->on_link_encryption_result(msg->param, link_encryption_t::NOT_ENCRYPTED);
             return true;
         }
 
         case DM_SEC_AUTH_REQ_IND: {
+            tr_info("Handling event DM_SEC_AUTH_REQ_IND");
             auto *evt = (dmSecAuthReqIndEvt_t *) msg;
             connection_handle_t connection = evt->hdr.param;
 
@@ -618,6 +670,7 @@ bool PalSecurityManager::sm_handler(const wsfMsgHdr_t *msg)
                         connection,
                         get_security_manager()._default_passkey
                     );
+                    tr_info("Use default passkey");
                     DmSecAuthRsp(
                         connection,
                         /* data length */ SMP_PIN_LEN,
@@ -625,6 +678,7 @@ bool PalSecurityManager::sm_handler(const wsfMsgHdr_t *msg)
                     );
                 } else {
                     /* generate random passkey, limit to 6 digit max */
+                    tr_info("Generate random passkey");
                     passkey_num_t passkey;
                     SecRand((uint8_t *) &passkey, sizeof(passkey));
                     passkey %= 1000000;
@@ -640,6 +694,7 @@ bool PalSecurityManager::sm_handler(const wsfMsgHdr_t *msg)
         }
 
         case DM_SEC_KEY_IND: {
+            tr_info("Handling event DM_SEC_KEY_IND");
             // NOTE: also report security level and encryption key len
             auto *evt = (dmSecKeyIndEvt_t *) msg;
             connection_handle_t connection = evt->hdr.param;
@@ -697,6 +752,7 @@ bool PalSecurityManager::sm_handler(const wsfMsgHdr_t *msg)
         }
 
         case DM_SEC_LTK_REQ_IND: {
+            tr_info("Handling event DM_SEC_LTK_REQ_IND");
             uint8_t null_rand[HCI_RAND_LEN] = {0};
             auto *evt = (hciLeLtkReqEvt_t *) msg;
 
@@ -717,6 +773,7 @@ bool PalSecurityManager::sm_handler(const wsfMsgHdr_t *msg)
 
 #if BLE_ROLE_PERIPHERAL
         case DM_SEC_PAIR_IND: {
+            tr_info("Handling event DM_SEC_PAIR_IND");
             auto *evt = (dmSecPairIndEvt_t *) msg;
             handler->on_pairing_request(
                 /* connection */ evt->hdr.param,
@@ -731,6 +788,7 @@ bool PalSecurityManager::sm_handler(const wsfMsgHdr_t *msg)
 
 #if BLE_ROLE_CENTRAL
         case DM_SEC_SLAVE_REQ_IND: {
+            tr_info("Handling event DM_SEC_SLAVE_REQ_IND");
             auto *evt = (dmSecPairIndEvt_t *) msg;
             handler->on_slave_security_request(
                 /* connection */ evt->hdr.param,
@@ -742,6 +800,7 @@ bool PalSecurityManager::sm_handler(const wsfMsgHdr_t *msg)
 
 #if BLE_FEATURE_SECURE_CONNECTIONS
         case DM_SEC_CALC_OOB_IND: {
+            tr_info("Handling event DM_SEC_CALC_OOB_IND");
             auto *evt = (dmSecOobCalcIndEvt_t *) msg;
             handler->on_secure_connections_oob_generated(
                 evt->random,
@@ -751,7 +810,12 @@ bool PalSecurityManager::sm_handler(const wsfMsgHdr_t *msg)
         }
 
         case DM_SEC_ECC_KEY_IND: {
+            tr_info("Handling event DM_SEC_ECC_KEY_IND");
             auto *evt = (secEccMsg_t *) msg;
+            tr_info("ECC Keys generated: public key x=%s, public key y=%s, private key=%s",
+                tr_array(evt->data.key.pubKey_x, SEC_ECC_KEY_LEN),
+                tr_array(evt->data.key.pubKey_y, SEC_ECC_KEY_LEN),
+                tr_array(evt->data.key.privKey, SEC_ECC_KEY_LEN));
             DmSecSetEccKey(&evt->data.key);
             memcpy(self._public_key_x, evt->data.key.pubKey_x, sizeof(self._public_key_x));
             self._lesc_keys_generated = true;
@@ -759,6 +823,7 @@ bool PalSecurityManager::sm_handler(const wsfMsgHdr_t *msg)
         }
 
         case DM_SEC_COMPARE_IND: {
+            tr_info("Handling event DM_SEC_COMPARE_IND");
             auto *evt = (dmSecCnfIndEvt_t *) msg;
             handler->on_passkey_display(
                 /* connection */ evt->hdr.param,
@@ -769,6 +834,7 @@ bool PalSecurityManager::sm_handler(const wsfMsgHdr_t *msg)
         }
 
         case DM_SEC_KEYPRESS_IND: {
+            tr_info("Handling event DM_SEC_KEYPRESS_IND");
             auto *evt = (dmSecKeypressIndEvt_t *) msg;
             handler->on_keypress_notification(
                 /* connection */ evt->hdr.param,

connectivity/FEATURE_BLE/source/generic/PrivateAddressController.cpp

@@ -18,6 +18,10 @@
 #if BLE_FEATURE_PRIVACY
 
 #include "PrivateAddressController.h"
+#include "mbed-trace/mbed_trace.h"
+#include "common/ble_trace_helpers.h"
+
+#define TRACE_GROUP "BLSM"
 
 namespace ble {
 
@@ -50,12 +54,14 @@ PrivateAddressController::~PrivateAddressController()
 
 void PrivateAddressController::set_local_irk(const irk_t &local_irk)
 {
+    tr_info("Set local irk: %s", to_string(local_irk));
     _local_irk = local_irk;
     generate_resolvable_address();
 }
 
 void PrivateAddressController::set_timeout(ble::resolvable_address_timeout_t rotation_timeout)
 {
+    tr_info("Set resolvable address timeout: %d s", rotation_timeout.value());
     _rotation_timeout = rotation_timeout;
     _pal.set_ll_resolvable_private_address_timeout(rotation_timeout);
     if (_generation_started) {
@@ -85,12 +91,15 @@ void PrivateAddressController::start_private_address_generation()
         return;
     }
 
+    tr_info("Start private address generation");
+
     // non resolvable private address generation has been delayed until now,
     // generate it.
     generate_non_resolvable_address();
 
     _address_rotation_ticker.attach([this] {
         _event_queue.post([this]{
+            tr_info("Private address timeout");
             generate_resolvable_address();
             generate_non_resolvable_address();
         });
@@ -101,6 +110,7 @@ void PrivateAddressController::start_private_address_generation()
 void PrivateAddressController::stop_private_address_generation()
 {
     if (_generation_started) {
+        tr_info("Stop private address generation");
         _address_rotation_ticker.detach();
         _generation_started = false;
     }
@@ -110,14 +120,19 @@ void PrivateAddressController::generate_resolvable_address()
 {
     if (_local_irk != irk_t{}) {
         _pal.generate_resolvable_private_address(_local_irk);
+    } else {
+        tr_warning("Failed to generate resolvable address, no local irk");
     }
 }
 
 void PrivateAddressController::on_resolvable_private_address_generated(const address_t &rpa)
 {
+    tr_info("Resolvable private address generated: %s", to_string(rpa));
     _resolvable_address = rpa;
     if (_event_handler) {
         _event_handler->on_resolvable_private_addresses_generated(_resolvable_address);
+    } else {
+        tr_warning("No app handler to receive RPA generated");
     }
 }
 
@@ -127,6 +142,8 @@ void PrivateAddressController::generate_non_resolvable_address()
     _event_queue.post([this] {
         if (_event_handler) {
             _event_handler->on_non_resolvable_private_addresses_generated(_non_resolvable_address);
+        } else {
+            tr_warning("No app handler to receive NRPA generated");
         }
     });
 }
@@ -168,7 +185,10 @@ ble_error_t PrivateAddressController::add_device_to_resolving_list(
     const irk_t& peer_irk
 )
 {
+    tr_info("Add device to resolving list: peer address=%s, type=%s, peer irk=%s",
+        to_string(peer_identity_address), to_string(peer_address_type), to_string(peer_irk));
     if (_local_irk == irk_t{}) {
+        tr_error("Invalid local IRK: %s", to_string(_local_irk));
         return BLE_ERROR_INVALID_STATE;
     }
 
@@ -198,6 +218,7 @@ ble_error_t PrivateAddressController::add_device_to_resolving_list(
     }
 
     if (!entry_added) {
+        tr_error("Failed to add address into host resolving list, not enough space");
         return BLE_ERROR_NO_MEM;
     }
 
@@ -221,6 +242,7 @@ ble_error_t PrivateAddressController::add_device_to_resolving_list(
             peer_irk
         );
     } else {
+        tr_error("Host based private address resolution enabled but not supported by the controller");
         return BLE_ERROR_NOT_IMPLEMENTED;
     }
 #endif // BLE_GAP_HOST_BASED_PRIVATE_ADDRESS_RESOLUTION
@@ -231,6 +253,8 @@ ble_error_t PrivateAddressController::remove_device_from_resolving_list(
     const address_t &peer_identity_address
 )
 {
+    tr_info("Remove device from resolving list: peer address=%s, type=%s",
+        to_string(peer_identity_address), to_string(peer_address_type));
 #if BLE_GAP_HOST_BASED_PRIVATE_ADDRESS_RESOLUTION
     for (auto &entry : _resolving_list) {
         if (entry.populated &&
@@ -252,6 +276,7 @@ ble_error_t PrivateAddressController::remove_device_from_resolving_list(
     if (is_controller_privacy_supported()) {
         return queue_remove_device_from_resolving_list(peer_address_type, peer_identity_address);
     } else {
+        tr_error("Host based private address resolution enabled but not supported by the controller");
         return BLE_ERROR_NOT_IMPLEMENTED;
     }
 #endif // BLE_GAP_HOST_BASED_PRIVATE_ADDRESS_RESOLUTION
@@ -259,6 +284,7 @@ ble_error_t PrivateAddressController::remove_device_from_resolving_list(
 
 ble_error_t PrivateAddressController::clear_resolving_list()
 {
+    tr_info("Clear resolving list");
 #if BLE_GAP_HOST_BASED_PRIVATE_ADDRESS_RESOLUTION
     // Remove entry from the resolving list
     for (auto &entry : _resolving_list) {
@@ -277,6 +303,7 @@ ble_error_t PrivateAddressController::clear_resolving_list()
     if (is_controller_privacy_supported()) {
         return queue_clear_resolving_list();
     } else {
+        tr_error("Host based private address resolution enabled but not supported by the controller");
         return BLE_ERROR_NOT_IMPLEMENTED;
     }
 #endif // BLE_GAP_HOST_BASED_PRIVATE_ADDRESS_RESOLUTION
@@ -310,12 +337,15 @@ bool PrivateAddressController::resolve_address_in_host_cache(
                 entry->next = _resolved_list;
                 _resolved_list = entry;
             }
+            tr_debug("Resolved address from cache: rpa=%s, resolved address=%s, type=%s",
+                to_string(peer_address), to_string(entry->identity->peer_address), to_string(entry->identity->peer_address_type));
             return true;
         }
         previous = entry;
         entry = entry->next;
     }
 
+    tr_debug("Address not found in cache: %s", to_string(peer_address));
     return false;
 }
 
@@ -340,6 +370,7 @@ ble_error_t PrivateAddressController::resolve_address_on_host(
 
 void PrivateAddressController::on_resolving_list_action_complete()
 {
+    tr_info("Resolving list action completed");
     process_privacy_control_blocks(true);
 }
 
@@ -412,6 +443,7 @@ ble_error_t PrivateAddressController::queue_add_device_to_resolving_list(
         peer_irk
     );
     if (cb == nullptr) {
+        tr_error("Failed to create control block to add device to resolving list");
         // Cannot go further
         return BLE_ERROR_NO_MEM;
     }
@@ -458,6 +490,7 @@ ble_error_t PrivateAddressController::queue_remove_device_from_resolving_list(
         peer_identity_address
     );
     if (cb == nullptr) {
+        tr_error("Failed to create control block to remove device from resolving list");
         // Cannot go further
         return BLE_ERROR_NO_MEM;
     }
@@ -488,6 +521,7 @@ ble_error_t PrivateAddressController::queue_clear_resolving_list()
 
     auto *cb = new(std::nothrow) PrivacyClearResListControlBlock();
     if (cb == nullptr) {
+        tr_error("Failed to create control block to clear resolving list");
         // Cannot go further
         return BLE_ERROR_NO_MEM;
     }
@@ -549,6 +583,7 @@ private:
             }
         } while (!self._resolving_list[resolving_list_index].populated);
 
+        tr_debug("Start resolution with next identity entry: %s", to_string(peer_address));
         start_resolution(self);
         return false;
     }
@@ -567,6 +602,13 @@ private:
         resolving_list_entry_t* identity
     )
     {
+        if (!resolved) {
+            tr_debug("Address resolution complete: rpa=%s, resolved=%s", to_string(peer_resolvable_address), to_string(resolved));
+        } else {
+            tr_debug("Address resolution complete: rpa=%s, resolved=%s, identity address=%s, type=%s",
+                to_string(peer_resolvable_address), to_string(resolved), to_string(identity->peer_address), to_string(identity->peer_address_type));
+        }
+
         // First we had the device to the resolution list
         self.add_resolution_entry_to_cache(peer_resolvable_address, identity);
 
@@ -591,6 +633,7 @@ ble_error_t PrivateAddressController::queue_resolve_address_on_host(const addres
     auto *cb = new(std::nothrow) PrivacyResolveAddressOnHost(peer_address);
     if (cb == nullptr) {
         // Cannot go further
+        tr_error("Not enough memory to queue host address resolution: %s", to_string(peer_address));
         return BLE_ERROR_NO_MEM;
     }
 
@@ -605,6 +648,7 @@ void PrivateAddressController::restart_resolution_process_on_host()
 {
     // if processing is active, restart the one running.
     if (_processing_privacy_control_block && _pending_privacy_control_blocks) {
+        tr_info("Restart host address resolution process");
         static_cast<PrivacyResolveAddressOnHost*>(_pending_privacy_control_blocks)->invalidate();
     }
 }
@@ -614,6 +658,7 @@ void PrivateAddressController::on_private_address_resolved(bool success)
     if (_pending_privacy_control_blocks == nullptr ||
         _processing_privacy_control_block == false
         ) {
+        tr_warning("Received unexpected address resolution event");
         return;
     }
 
@@ -625,6 +670,7 @@ void PrivateAddressController::on_private_address_resolved(bool success)
 
 void PrivateAddressController::clear_privacy_control_blocks()
 {
+    tr_info("Clear privacy control blocks");
     while (_pending_privacy_control_blocks != nullptr) {
         PrivacyControlBlock *next = _pending_privacy_control_blocks->next();
         delete _pending_privacy_control_blocks;
@@ -634,6 +680,7 @@ void PrivateAddressController::clear_privacy_control_blocks()
 
 void PrivateAddressController::queue_privacy_control_block(PrivacyControlBlock *block)
 {
+    tr_info("Queue privacy request");
     if (_pending_privacy_control_blocks == nullptr) {
         _pending_privacy_control_blocks = block;
     } else {