BLE: Security Manager traces #14118

pan- · 2021-01-06T09:06:29Z

Summary of changes

Traces added to Bluetooth Security Manager.

Complete SecurityManager
Move String serialization into own file
Add traces to PAL

Documentation

Pull request type

[x] Patch update (Bug fix / Target update / Docs update / Test update / Refactor)
[] Feature update (New feature / Functionality change / New API)
[] Major update (Breaking change E.g. Return code change / API behaviour change)

Test results

[x] No Tests required for this change (E.g docs only update)
[] Covered by existing mbed-os tests (Greentea or Unittest)
[] Tests / results supplied as part of this PR

Reviewers

paul-szczepanek-arm · 2021-01-06T10:25:25Z

connectivity/FEATURE_BLE/source/generic/SecurityManagerImpl.cpp

+        to_string(iocaps),
+        passkey_str(passkey),
+        to_string(signing),
+        db_path


~~it's a string, though I understand it can be null~~ nevermind it's traced later

paul-szczepanek-arm · 2021-01-06T10:30:05Z

connectivity/FEATURE_BLE/source/generic/SecurityManagerImpl.cpp

+    if (!_db) {
+        tr_error("Failure, DB not initialized");
+        return BLE_ERROR_INITIALIZATION_INCOMPLETE;
+    }


line 349 can fail without trace if _pal.set_csrk doesn't log traces

But it will log trace, generaly, when the step is error = operation; if (error) { return error; } We can assume (in this context) that operation will trace the error and details of the call.

I don't want to trace errors twice if it doesn't add meaningful information.

yeah, as long as tracing is also added to pal

paul-szczepanek-arm · 2021-01-06T10:35:36Z

connectivity/FEATURE_BLE/source/generic/SecurityManagerImpl.cpp

+                    identity ? identity->identity_address_is_public : false
+                );
+            } else {
+                tr_warning("Event handler removing while retrieving peer ID address");


Suggested change

tr_warning("Event handler removing while retrieving peer ID address");

tr_warning("Event handler removed while retrieving peer ID address");

paul-szczepanek-arm · 2021-01-06T10:37:03Z

connectivity/FEATURE_BLE/source/generic/SecurityManagerImpl.cpp

        return BLE_ERROR_INVALID_PARAM;
    }

    if (cb->encryption_requested) {
+        tr_error("Failure, encryption already requested");


wouldn't class it as an error, since it's already pending you will actually get what you wnted

actually no, you could ask for something more

paul-szczepanek-arm · 2021-01-06T10:40:10Z

connectivity/FEATURE_BLE/source/generic/SecurityManagerImpl.cpp

@@ -537,18 +750,21 @@ ble_error_t SecurityManager::enableSigning(
                cb->db_entry
            );
        } else {
+            tr_info("CSRK not available, pair to acquire it");


Suggested change

tr_info("CSRK not available, pair to acquire it");

tr_info("CSRK not available, pairing to acquire it");

otherwise it implies user action was needed

actually if you're slave you can't force that so maybe the trace should be in the if statement where the role is known

paul-szczepanek-arm · 2021-01-06T10:46:23Z

connectivity/FEATURE_BLE/source/generic/SecurityManagerImpl.cpp

        return BLE_ERROR_INVALID_PARAM;
    }

    SecurityDistributionFlags_t* flags = _db->get_distribution_flags(cb->db_entry);
    if (!flags) {
+        tr_error("Failed to retrieve link encryption, empty distribution flags for %d", connection);


now I think about it, this can't ever happen, if entry exists it contains flags

It is present in many places, it can happen if the database is corrupted. I wonder if we shouldn't check it when it is loaded then assume it is consistent.

paul-szczepanek-arm · 2021-01-06T10:48:13Z

connectivity/FEATURE_BLE/source/generic/SecurityManagerImpl.cpp

@@ -613,30 +835,38 @@ ble_error_t SecurityManager::setLinkEncryption(
    link_encryption_t encryption
 )
 {
-    if (!_db) return BLE_ERROR_INITIALIZATION_INCOMPLETE;
+    tr_info("Set %d encryption to %s", connection, to_string(encryption));


The problem with logs that are only meaningful in pairs is that tracing may be broken up by other traces and becomes hard to read when the meaning of a line depends on a line potentially N lines lower and you will not know if it's there or which statement it links to.

I think each trace should be self contained.

In the case of an unfiltered log, I think you make a good point. However, if you filter the log by trace group, the stream of traces should be clearer.

paul-szczepanek-arm · 2021-01-06T10:51:26Z

connectivity/FEATURE_BLE/source/generic/SecurityManagerImpl.cpp

        return BLE_ERROR_INVALID_PARAM;
    }

-    eventHandler->linkEncryptionResult(connection, current_encryption);
+    if (eventHandler) {


nice catch, maybe worth a separate commit

paul-szczepanek-arm

Very comprehensive. I have my doubts about the context sensitive traces approach.

I don't like tracing whose interpretations relies on more than one line, lines can be broken up and then you can't tell if an action completed correctly or not because even if there is a error trace then you might connect it to the wrong trace line.

Exception are OK, like for example it doesn't matter what causes the "DB not initialised" trace, because it's a global db so it just means it's not there, doesn't matter what caused the discovery of it being missing.

- 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 `,`.

pan- · 2021-01-06T19:35:15Z

@paul-szczepanek-arm @noonfom I have updated the PR and it is ready for a more formal review.

Here's some logs to see the end result:

Only the first 8 bytes were generated from the stack.

mergify · 2021-01-08T12:05:35Z

This PR cannot be merged due to conflicts. Please rebase to resolve them.

pan- requested review from paul-szczepanek-arm and a user January 6, 2021 09:06

mergify bot added release-version: feature branch do not merge labels Jan 6, 2021

pan- added component: ble needs: work scope: refactor labels Jan 6, 2021

paul-szczepanek-arm reviewed Jan 6, 2021

View reviewed changes

paul-szczepanek-arm approved these changes Jan 6, 2021

View reviewed changes

WIP: SM Bluetooth traces

45b4ee7

pan- force-pushed the ble-add-sm-trace branch from 93acc6d to 45b4ee7 Compare January 6, 2021 16:20

pan- added 4 commits January 6, 2021 17:08

BLE: Move traces helper into their own file

fde273e

BLE: Move traces helper into their own file

860f21b

BLE: Add traces to Security Manager PAL

e50adec

BLE: Make SM traces consistent.

73ca2ba

- 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 `,`.

pan- changed the title ~~WIP: SM Bluetooth traces~~ BLE: Security Manager traces Jan 7, 2021

pan- added 2 commits January 7, 2021 12:32

BLE: Fix SM random number generation.

1648061

Only the first 8 bytes were generated from the stack.

BLE: Regenerate CSRK if it is all zeroes.

bab5bb3

pan- mentioned this pull request Jan 7, 2021

BLE: Add privacy trace #14127

Merged

pan- closed this Jan 8, 2021

mergify bot removed component: ble do not merge needs: work release-version: feature branch scope: refactor labels Jan 8, 2021

	tr_warning("Event handler removing while retrieving peer ID address");
	tr_warning("Event handler removed while retrieving peer ID address");

	tr_info("CSRK not available, pair to acquire it");
	tr_info("CSRK not available, pairing to acquire it");

BLE: Security Manager traces #14118

BLE: Security Manager traces #14118

Uh oh!

Conversation

pan- commented Jan 6, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Summary of changes

Documentation

Pull request type

Test results

Reviewers

Uh oh!

paul-szczepanek-arm Jan 6, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

paul-szczepanek-arm Jan 6, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

paul-szczepanek-arm left a comment

Choose a reason for hiding this comment

Uh oh!

pan- commented Jan 6, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

mergify bot commented Jan 8, 2021

Uh oh!

Uh oh!

pan- commented Jan 6, 2021 •

edited

Loading

paul-szczepanek-arm Jan 6, 2021 •

edited

Loading

paul-szczepanek-arm Jan 6, 2021 •

edited

Loading

pan- commented Jan 6, 2021 •

edited

Loading