BLE: Add privacy trace (ARMmbed#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.

Author: pan-

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,16 +204,19 @@ PalPrivateAddressController& PalPrivateAddressController::instance()
 bool PalPrivateAddressController::cordio_handler(const wsfMsgHdr_t *msg)
 {
     if (msg == nullptr) {
+        tr_warning("Privacy handler received null message");
         return false;
     }
 
     auto* handler = instance()._event_handler;
 
     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;
             }