[Darwin] Adding more metrics to capture BLE during setup (project-chip#32793)

- Added more metrics across BLE phase in Darwin
- Fixed MetricsCollector to only capture first event of any kind
- Reset metrics before any API is started
- Fixed bug where duration was not being calculated correctly

Author: anush-apple

src/darwin/Framework/CHIP/MTRCommissionableBrowser.mm

@@ -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>
@@ -35,6 +37,8 @@
 
 constexpr char kBleKey[] = "BLE";
 
+using namespace chip::Tracing::DarwinFramework;
+
 @implementation MTRCommissionableBrowserResultInterfaces
 @end
 
@@ -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));
@@ -100,6 +105,7 @@ CHIP_ERROR Stop()
 
         ClearBleDiscoveredDevices();
         ClearDnssdDiscoveredDevices();
+        ResetCounters();
         mDiscoveredResults = nil;
 
 #if CONFIG_NETWORK_LAYER_BLE
@@ -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;
@@ -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];
@@ -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.
@@ -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;
 
@@ -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];
         });
@@ -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 ()

src/darwin/Framework/CHIP/MTRDeviceController.mm

@@ -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"
@@ -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);
@@ -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
@@ -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];
     };
 
@@ -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);
@@ -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];
@@ -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.
@@ -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) {
@@ -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;
                 }
             }
@@ -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);
 
@@ -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;
@@ -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];
     };
 
@@ -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);
 
@@ -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;
@@ -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];
     };
 
@@ -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]);
@@ -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];
     };
 

src/darwin/Framework/CHIP/MTRDeviceControllerDelegateBridge.h

@@ -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);
 };

src/darwin/Framework/CHIP/MTRDeviceControllerDelegateBridge.mm

@@ -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) {
@@ -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);
+        }
     }
 }
 
 void MTRDeviceControllerDelegateBridge::OnPairingComplete(CHIP_ERROR error)
 {
     MTR_LOG_DEFAULT("DeviceControllerDelegate Pairing complete. Status %s", chip::ErrorStr(error));
+    MATTER_LOG_METRIC_END(kMetricSetupPASESession, error);
 
     id<MTRDeviceControllerDelegate> strongDelegate = mDelegate;
     MTRDeviceController * strongController = mController;
@@ -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:)]) {
@@ -158,6 +175,11 @@
     }
 }
 
+void MTRDeviceControllerDelegateBridge::SetDeviceNodeID(chip::NodeId deviceNodeId)
+{
+    mDeviceNodeId = deviceNodeId;
+}
+
 @implementation MTRProductIdentity
 
 - (instancetype)initWithVendorID:(NSNumber *)vendorID productID:(NSNumber *)productID