Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Darwin] Adding more metrics to capture BLE during setup #32793

Merged
merged 1 commit into from
Mar 29, 2024
Merged

[Darwin] Adding more metrics to capture BLE during setup #32793

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
24 changes: 24 additions & 0 deletions src/darwin/Framework/CHIP/MTRCommissionableBrowser.mm
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,8 @@
#import "MTRCommissionableBrowserResult_Internal.h"
#import "MTRDeviceController.h"
#import "MTRLogging_Internal.h"
#import "MTRMetricKeys.h"
#include <tracing/metric_macros.h>

#include <controller/CHIPDeviceController.h>
#include <lib/dnssd/platform/Dnssd.h>
Expand All @@ -35,6 +37,8 @@

constexpr char kBleKey[] = "BLE";

using namespace chip::Tracing::DarwinFramework;

@implementation MTRCommissionableBrowserResultInterfaces
@end

Expand Down Expand Up @@ -70,6 +74,7 @@ CHIP_ERROR Start(id<MTRCommissionableBrowserDelegate> delegate, MTRDeviceControl
mController = controller;
mDispatchQueue = queue;
mDiscoveredResults = [[NSMutableDictionary alloc] init];
ResetCounters();

#if CONFIG_NETWORK_LAYER_BLE
ReturnErrorOnFailure(PlatformMgrImpl().StartBleScan(this));
Expand Down Expand Up @@ -100,6 +105,7 @@ CHIP_ERROR Stop()

ClearBleDiscoveredDevices();
ClearDnssdDiscoveredDevices();
ResetCounters();
mDiscoveredResults = nil;

#if CONFIG_NETWORK_LAYER_BLE
Expand All @@ -109,6 +115,12 @@ CHIP_ERROR Stop()
return ChipDnssdStopBrowse(this);
}

void ResetCounters()
{
mOnNetworkDevicesAdded = mOnNetworkDevicesRemoved = 0;
mBLEDevicesAdded = mBLEDevicesRemoved = 0;
}

void ClearBleDiscoveredDevices()
{
NSMutableDictionary<NSString *, MTRCommissionableBrowserResult *> * discoveredResultsCopy = @ {}.mutableCopy;
Expand Down Expand Up @@ -197,6 +209,8 @@ void OnBrowseAdd(DnssdService service) override
VerifyOrReturn(mController != nil);
VerifyOrReturn(mDispatchQueue != nil);

MATTER_LOG_METRIC(kMetricOnNetworkDevicesAdded, ++mOnNetworkDevicesAdded);

auto key = [NSString stringWithUTF8String:service.mName];
if ([mDiscoveredResults objectForKey:key] == nil) {
mDiscoveredResults[key] = [[MTRCommissionableBrowserResult alloc] init];
Expand All @@ -218,6 +232,8 @@ void OnBrowseRemove(DnssdService service) override
VerifyOrReturn(mController != nil);
VerifyOrReturn(mDispatchQueue != nil);

MATTER_LOG_METRIC(kMetricOnNetworkDevicesRemoved, ++mOnNetworkDevicesRemoved);

auto key = [NSString stringWithUTF8String:service.mName];
if ([mDiscoveredResults objectForKey:key] == nil) {
// It should not happens.
Expand Down Expand Up @@ -269,6 +285,8 @@ void OnBleScanAdd(BLE_CONNECTION_OBJECT connObj, const ChipBLEDeviceIdentificati
result.commissioningMode = YES;
result.params = chip::MakeOptional(chip::Controller::SetUpCodePairerParameters(connObj, false /* connected */));

MATTER_LOG_METRIC(kMetricBLEDevicesAdded, ++mBLEDevicesAdded);

auto key = [NSString stringWithFormat:@"%@", connObj];
mDiscoveredResults[key] = result;

Expand All @@ -290,6 +308,8 @@ void OnBleScanRemove(BLE_CONNECTION_OBJECT connObj) override
auto result = mDiscoveredResults[key];
mDiscoveredResults[key] = nil;

MATTER_LOG_METRIC(kMetricBLEDevicesRemoved, ++mBLEDevicesRemoved);

dispatch_async(mDispatchQueue, ^{
[mDelegate controller:mController didFindCommissionableDevice:result];
});
Expand All @@ -301,6 +321,10 @@ void OnBleScanRemove(BLE_CONNECTION_OBJECT connObj) override
id<MTRCommissionableBrowserDelegate> mDelegate;
MTRDeviceController * mController;
NSMutableDictionary<NSString *, MTRCommissionableBrowserResult *> * mDiscoveredResults;
int32_t mOnNetworkDevicesAdded;
int32_t mOnNetworkDevicesRemoved;
int32_t mBLEDevicesAdded;
int32_t mBLEDevicesRemoved;
};

@interface MTRCommissionableBrowser ()
Expand Down
53 changes: 46 additions & 7 deletions src/darwin/Framework/CHIP/MTRDeviceController.mm
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -40,6 +40,7 @@
#import "MTRKeypair.h"
#import "MTRLogging_Internal.h"
#import "MTRMetricKeys.h"
#import "MTRMetricsCollector.h"
#import "MTROperationalCredentialsDelegate.h"
#import "MTRP256KeypairBridge.h"
#import "MTRPersistentStorageDelegateBridge.h"
Expand Down Expand Up @@ -610,10 +611,18 @@ static inline void emitMetricForSetupPayload(MTRSetupPayload * payload)
MATTER_LOG_METRIC(kMetricDeviceProductID, [payload.productID unsignedIntValue]);
}

- (void)preparePASESessionMetric:(chip::NodeId)nodeId
{
self->_deviceControllerDelegateBridge->SetDeviceNodeID(nodeId);
MATTER_LOG_METRIC_BEGIN(kMetricSetupPASESession);
}

- (BOOL)setupCommissioningSessionWithPayload:(MTRSetupPayload *)payload
newNodeID:(NSNumber *)newNodeID
error:(NSError * __autoreleasing *)error
{
[[MTRMetricsCollector sharedInstance] resetMetrics];

// Track overall commissioning
MATTER_LOG_METRIC_BEGIN(kMetricDeviceCommissioning);
emitMetricForSetupPayload(payload);
Expand All @@ -623,7 +632,7 @@ - (BOOL)setupCommissioningSessionWithPayload:(MTRSetupPayload *)payload
__block CHIP_ERROR errorCode = CHIP_NO_ERROR;

auto block = ^BOOL {
// Track just this portion of overall PASE setup
// Track work until end of scope
MATTER_LOG_METRIC_SCOPE(kMetricSetupWithPayload, errorCode);

// Try to get a QR code if possible (because it has a better
Expand All @@ -633,12 +642,17 @@ - (BOOL)setupCommissioningSessionWithPayload:(MTRSetupPayload *)payload
pairingCode = [payload manualEntryCode];
}
if (pairingCode == nil) {
return ![MTRDeviceController checkForError:CHIP_ERROR_INVALID_ARGUMENT logMsg:kErrorSetupCodeGen error:error];
errorCode = CHIP_ERROR_INVALID_ARGUMENT;
return ![MTRDeviceController checkForError:errorCode logMsg:kErrorSetupCodeGen error:error];
}

chip::NodeId nodeId = [newNodeID unsignedLongLongValue];
self->_operationalCredentialsDelegate->SetDeviceID(nodeId);

[self preparePASESessionMetric:nodeId];
errorCode = self->_cppCommissioner->EstablishPASEConnection(nodeId, [pairingCode UTF8String]);
VerifyOrDo(errorCode != CHIP_NO_ERROR, MATTER_LOG_METRIC_END(kMetricSetupPASESession, errorCode));

return ![MTRDeviceController checkForError:errorCode logMsg:kErrorPairDevice error:error];
};

Expand All @@ -654,6 +668,8 @@ - (BOOL)setupCommissioningSessionWithDiscoveredDevice:(MTRCommissionableBrowserR
newNodeID:(NSNumber *)newNodeID
error:(NSError * __autoreleasing *)error
{
[[MTRMetricsCollector sharedInstance] resetMetrics];

// Track overall commissioning
MATTER_LOG_METRIC_BEGIN(kMetricDeviceCommissioning);
emitMetricForSetupPayload(payload);
Expand All @@ -663,7 +679,7 @@ - (BOOL)setupCommissioningSessionWithDiscoveredDevice:(MTRCommissionableBrowserR
__block CHIP_ERROR errorCode = CHIP_NO_ERROR;

auto block = ^BOOL {
// Track just this portion of overall PASE setup
// Track work until end of scope
MATTER_LOG_METRIC_SCOPE(kMetricSetupWithDiscovered, errorCode);

chip::NodeId nodeId = [newNodeID unsignedLongLongValue];
Expand All @@ -675,7 +691,9 @@ - (BOOL)setupCommissioningSessionWithDiscoveredDevice:(MTRCommissionableBrowserR
auto pinCode = static_cast<uint32_t>(payload.setupPasscode.unsignedLongValue);
params.Value().SetSetupPINCode(pinCode);

[self preparePASESessionMetric:nodeId];
errorCode = self->_cppCommissioner->EstablishPASEConnection(nodeId, params.Value());
VerifyOrDo(errorCode != CHIP_NO_ERROR, MATTER_LOG_METRIC_END(kMetricSetupPASESession, errorCode));
} else {
// Try to get a QR code if possible (because it has a better
// discriminator, etc), then fall back to manual code if that fails.
Expand All @@ -684,7 +702,8 @@ - (BOOL)setupCommissioningSessionWithDiscoveredDevice:(MTRCommissionableBrowserR
pairingCode = [payload manualEntryCode];
}
if (pairingCode == nil) {
return ![MTRDeviceController checkForError:CHIP_ERROR_INVALID_ARGUMENT logMsg:kErrorSetupCodeGen error:error];
errorCode = CHIP_ERROR_INVALID_ARGUMENT;
return ![MTRDeviceController checkForError:errorCode logMsg:kErrorSetupCodeGen error:error];
}

for (id key in discoveredDevice.interfaces) {
Expand All @@ -693,9 +712,11 @@ - (BOOL)setupCommissioningSessionWithDiscoveredDevice:(MTRCommissionableBrowserR
continue;
}

[self preparePASESessionMetric:nodeId];
errorCode = self->_cppCommissioner->EstablishPASEConnection(
nodeId, [pairingCode UTF8String], chip::Controller::DiscoveryType::kDiscoveryNetworkOnly, resolutionData);
if (CHIP_NO_ERROR != errorCode) {
MATTER_LOG_METRIC_END(kMetricSetupPASESession, errorCode);
break;
}
}
Expand Down Expand Up @@ -1616,6 +1637,8 @@ - (BOOL)pairDevice:(uint64_t)deviceID
setupPINCode:(uint32_t)setupPINCode
error:(NSError * __autoreleasing *)error
{
[[MTRMetricsCollector sharedInstance] resetMetrics];

// Track overall commissioning
MATTER_LOG_METRIC_BEGIN(kMetricDeviceCommissioning);

Expand All @@ -1624,7 +1647,7 @@ - (BOOL)pairDevice:(uint64_t)deviceID
__block CHIP_ERROR errorCode = CHIP_NO_ERROR;

auto block = ^BOOL {
// Track just this portion of overall PASE setup
// Track work until end of scope
MATTER_LOG_METRIC_SCOPE(kMetricPairDevice, errorCode);

std::string manualPairingCode;
Expand All @@ -1636,7 +1659,11 @@ - (BOOL)pairDevice:(uint64_t)deviceID
VerifyOrReturnValue(![MTRDeviceController checkForError:errorCode logMsg:kErrorSetupCodeGen error:error], NO);

self->_operationalCredentialsDelegate->SetDeviceID(deviceID);

[self preparePASESessionMetric:deviceID];
errorCode = self->_cppCommissioner->EstablishPASEConnection(deviceID, manualPairingCode.c_str());
VerifyOrDo(errorCode != CHIP_NO_ERROR, MATTER_LOG_METRIC_END(kMetricSetupPASESession, errorCode));

return ![MTRDeviceController checkForError:errorCode logMsg:kErrorPairDevice error:error];
};

Expand All @@ -1653,6 +1680,8 @@ - (BOOL)pairDevice:(uint64_t)deviceID
setupPINCode:(uint32_t)setupPINCode
error:(NSError * __autoreleasing *)error
{
[[MTRMetricsCollector sharedInstance] resetMetrics];

// Track overall commissioning
MATTER_LOG_METRIC_BEGIN(kMetricDeviceCommissioning);

Expand All @@ -1661,7 +1690,7 @@ - (BOOL)pairDevice:(uint64_t)deviceID
__block CHIP_ERROR errorCode = CHIP_NO_ERROR;

auto block = ^BOOL {
// Track just this portion of overall PASE setup
// Track work until end of scope
MATTER_LOG_METRIC_SCOPE(kMetricPairDevice, errorCode);

chip::Inet::IPAddress addr;
Expand All @@ -1671,7 +1700,11 @@ - (BOOL)pairDevice:(uint64_t)deviceID
self->_operationalCredentialsDelegate->SetDeviceID(deviceID);

auto params = chip::RendezvousParameters().SetSetupPINCode(setupPINCode).SetPeerAddress(peerAddress);

[self preparePASESessionMetric:deviceID];
errorCode = self->_cppCommissioner->EstablishPASEConnection(deviceID, params);
VerifyOrDo(errorCode != CHIP_NO_ERROR, MATTER_LOG_METRIC_END(kMetricSetupPASESession, errorCode));

return ![MTRDeviceController checkForError:errorCode logMsg:kErrorPairDevice error:error];
};

Expand All @@ -1684,6 +1717,8 @@ - (BOOL)pairDevice:(uint64_t)deviceID

- (BOOL)pairDevice:(uint64_t)deviceID onboardingPayload:(NSString *)onboardingPayload error:(NSError * __autoreleasing *)error
{
[[MTRMetricsCollector sharedInstance] resetMetrics];

// Track overall commissioning
MATTER_LOG_METRIC_BEGIN(kMetricDeviceCommissioning);
emitMetricForSetupPayload([MTRSetupPayload setupPayloadWithOnboardingPayload:onboardingPayload error:nil]);
Expand All @@ -1693,11 +1728,15 @@ - (BOOL)pairDevice:(uint64_t)deviceID onboardingPayload:(NSString *)onboardingPa
__block CHIP_ERROR errorCode = CHIP_NO_ERROR;

auto block = ^BOOL {
// Track just this portion of overall PASE setup
// Track work until end of scope
MATTER_LOG_METRIC_SCOPE(kMetricPairDevice, errorCode);

self->_operationalCredentialsDelegate->SetDeviceID(deviceID);

[self preparePASESessionMetric:deviceID];
errorCode = self->_cppCommissioner->EstablishPASEConnection(deviceID, [onboardingPayload UTF8String]);
VerifyOrDo(errorCode != CHIP_NO_ERROR, MATTER_LOG_METRIC_END(kMetricSetupPASESession, errorCode));

return ![MTRDeviceController checkForError:errorCode logMsg:kErrorPairDevice error:error];
};

Expand Down
3 changes: 3 additions & 0 deletions src/darwin/Framework/CHIP/MTRDeviceControllerDelegateBridge.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -42,10 +42,13 @@ class MTRDeviceControllerDelegateBridge : public chip::Controller::DevicePairing

void OnCommissioningComplete(chip::NodeId deviceId, CHIP_ERROR error) override;

void SetDeviceNodeID(chip::NodeId deviceNodeId);

private:
MTRDeviceController * __weak mController;
_Nullable id<MTRDeviceControllerDelegate> mDelegate;
_Nullable dispatch_queue_t mQueue;
chip::NodeId mDeviceNodeId;

MTRCommissioningStatus MapStatus(chip::Controller::DevicePairingDelegate::Status status);
};
Expand Down
22 changes: 22 additions & 0 deletions src/darwin/Framework/CHIP/MTRDeviceControllerDelegateBridge.mm
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -64,6 +64,13 @@
{
MTR_LOG_DEFAULT("DeviceControllerDelegate status updated: %d", status);

// If pairing failed, PASE failed. However, since OnPairingComplete(failure_code) might not be invoked in all cases, mark
// end of PASE with timeout as assumed failure. If OnPairingComplete is invoked, the right error code will be updated in
// the end event
if (status == chip::Controller::DevicePairingDelegate::Status::SecurePairingFailed) {
MATTER_LOG_METRIC_END(kMetricSetupPASESession, CHIP_ERROR_TIMEOUT);
}

id<MTRDeviceControllerDelegate> strongDelegate = mDelegate;
MTRDeviceController * strongController = mController;
if (strongDelegate && mQueue && strongController) {
Expand All @@ -73,12 +80,21 @@
[strongDelegate controller:strongController statusUpdate:commissioningStatus];
});
}

// If PASE session setup fails and the client implements the delegate that accepts metrics, invoke the delegate
// to mark end of commissioning request.
// Since OnPairingComplete(failure_code) might not be invoked in all cases, use this opportunity to inform of failed commissioning
// and default the error to timeout since that is best guess in this layer.
if (status == chip::Controller::DevicePairingDelegate::Status::SecurePairingFailed && [strongDelegate respondsToSelector:@selector(controller:commissioningComplete:nodeID:metrics:)]) {
OnCommissioningComplete(mDeviceNodeId, CHIP_ERROR_TIMEOUT);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This needs to be documented clearly in the APIs. Given what the documentation says right now, API consumers will absolutely not expect a commissioningComplete callback here.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

But if the API consumer tries to set up a new PASE session while the old setup is in progress, what happens? That will clobber mDeviceNodeId, right? Because we set it before we try to do the new PASE setup, which I think will fail out sync in that case...

This really needs an actual sound model for how this stuff works, so we don't get stuck with behavior clients expect that is broken and we can't change.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yup, but I am not sure how to fix this without changing the C++ layer. Ideally, if the callbacks can be fixed to pass on the NodeId, it will eliminate this issue

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Well, one option is to set this only if we successfully kick off an async pairing operation, right? As in, don't set this until the call into the C++ returns success.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

But in that case, the callback above won't be invoked and clobbering the NodeId for the latest one should be fine. Right?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So the situation is:

  1. Start PASE with node id 1.
  2. Try to start PASE with node id 2, that fails to start (because the core SDK can only do one thing at a time for now), but sets mDeviceNodeId to 2.
  3. Now PASE to node id 1 fails, reports OnCommissioningComplete for node id 2.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah I see, I can fix it in next iteration

}
}
}

void MTRDeviceControllerDelegateBridge::OnPairingComplete(CHIP_ERROR error)
{
MTR_LOG_DEFAULT("DeviceControllerDelegate Pairing complete. Status %s", chip::ErrorStr(error));
MATTER_LOG_METRIC_END(kMetricSetupPASESession, error);
woody-apple marked this conversation as resolved.
Show resolved Hide resolved

id<MTRDeviceControllerDelegate> strongDelegate = mDelegate;
MTRDeviceController * strongController = mController;
Expand Down Expand Up @@ -129,6 +145,7 @@

// Always collect the metrics to avoid unbounded growth of the stats in the collector
MTRMetrics * metrics = [[MTRMetricsCollector sharedInstance] metricSnapshot:TRUE];
MTR_LOG_INFO("Device commissioning complete with metrics %@", metrics);

if ([strongDelegate respondsToSelector:@selector(controller:commissioningComplete:nodeID:)] ||
[strongDelegate respondsToSelector:@selector(controller:commissioningComplete:nodeID:metrics:)]) {
Expand Down Expand Up @@ -158,6 +175,11 @@
}
}

void MTRDeviceControllerDelegateBridge::SetDeviceNodeID(chip::NodeId deviceNodeId)
{
mDeviceNodeId = deviceNodeId;
}

@implementation MTRProductIdentity

- (instancetype)initWithVendorID:(NSNumber *)vendorID productID:(NSNumber *)productID
Expand Down
Loading
Loading