[Metrics] Metrics in core commissioning phase (#33247)

* [Metrics] Metrics in core commissioning phase

- Added metrics tracing in core parts of the commissionning flow:
  - PASE
  - OperationalSessionSetup
  - Different stages of commissioning

* Fixing code review comments

* Fixed a typo

* Fixed Code Review Comment

* Update src/app/OperationalSessionSetup.cpp

Co-authored-by: Boris Zbarsky <bzbarsky@apple.com>

* Resytler fixes

---------

Co-authored-by: Boris Zbarsky <bzbarsky@apple.com>

Author: anush-apple

src/app/OperationalSessionSetup.cpp

@@ -38,11 +38,13 @@
 #include <lib/support/logging/CHIPLogging.h>
 #include <system/SystemClock.h>
 #include <system/SystemLayer.h>
+#include <tracing/metric_event.h>
 
 using namespace chip::Callback;
 using chip::AddressResolve::NodeLookupRequest;
 using chip::AddressResolve::Resolver;
 using chip::AddressResolve::ResolveResult;
+using namespace chip::Tracing;
 
 namespace chip {
 
@@ -305,9 +307,11 @@ CHIP_ERROR OperationalSessionSetup::EstablishConnection(const ReliableMessagePro
     mCASEClient = mClientPool->Allocate();
     ReturnErrorCodeIf(mCASEClient == nullptr, CHIP_ERROR_NO_MEMORY);
 
+    MATTER_LOG_METRIC_BEGIN(kMetricDeviceCASESession);
     CHIP_ERROR err = mCASEClient->EstablishSession(mInitParams, mPeerId, mDeviceAddress, config, this);
     if (err != CHIP_NO_ERROR)
     {
+        MATTER_LOG_METRIC_END(kMetricDeviceCASESession, err);
         CleanupCASEClient();
         return err;
     }
@@ -503,6 +507,10 @@ void OperationalSessionSetup::OnSessionEstablishmentError(CHIP_ERROR error, Sess
 #endif // CHIP_DEVICE_CONFIG_ENABLE_AUTOMATIC_CASE_RETRIES
     }
 
+    // Session failed to be established. This is when discovery is also stopped
+    MATTER_LOG_METRIC_END(kMetricDeviceOperationalDiscovery, error);
+    MATTER_LOG_METRIC_END(kMetricDeviceCASESession, error);
+
     DequeueConnectionCallbacks(error, stage);
     // Do not touch `this` instance anymore; it has been destroyed in DequeueConnectionCallbacks.
 }
@@ -521,6 +529,11 @@ void OperationalSessionSetup::OnSessionEstablished(const SessionHandle & session
     VerifyOrReturn(mState == State::Connecting,
                    ChipLogError(Discovery, "OnSessionEstablished was called while we were not connecting"));
 
+    // Session has been established. This is when discovery is also stopped
+    MATTER_LOG_METRIC_END(kMetricDeviceOperationalDiscovery, CHIP_NO_ERROR);
+
+    MATTER_LOG_METRIC_END(kMetricDeviceCASESession, CHIP_NO_ERROR);
+
     if (!mSecureSession.Grab(session))
     {
         // Got an invalid session, just dispatch an error.  We have to do this
@@ -591,6 +604,7 @@ CHIP_ERROR OperationalSessionSetup::LookupPeerAddress()
     {
         --mResolveAttemptsAllowed;
     }
+    MATTER_LOG_METRIC(kMetricDeviceOperationalDiscoveryAttemptCount, mAttemptsDone);
 #endif // CHIP_DEVICE_CONFIG_ENABLE_AUTOMATIC_CASE_RETRIES
 
     // NOTE: This is public API that can be used to update our stored peer
@@ -605,6 +619,10 @@ CHIP_ERROR OperationalSessionSetup::LookupPeerAddress()
         return CHIP_NO_ERROR;
     }
 
+    // This code can be reached multiple times, if we discover multiple addresses or do retries.
+    // The metric backend can handle this and always picks the earliest occurrence as the start of the event.
+    MATTER_LOG_METRIC_BEGIN(kMetricDeviceOperationalDiscovery);
+
     auto const * fabricInfo = mInitParams.fabricTable->FindFabricWithIndex(mPeerId.GetFabricIndex());
     VerifyOrReturnError(fabricInfo != nullptr, CHIP_ERROR_INVALID_FABRIC_INDEX);
 
@@ -676,6 +694,8 @@ void OperationalSessionSetup::OnNodeAddressResolutionFailed(const PeerId & peerI
             --mAttemptsDone;
         }
 
+        MATTER_LOG_METRIC(kMetricDeviceOperationalDiscoveryAttemptCount, mAttemptsDone);
+
         CHIP_ERROR err = LookupPeerAddress();
         if (err == CHIP_NO_ERROR)
         {
@@ -690,6 +710,8 @@ void OperationalSessionSetup::OnNodeAddressResolutionFailed(const PeerId & peerI
     }
 #endif
 
+    MATTER_LOG_METRIC_END(kMetricDeviceOperationalDiscovery, reason);
+
     // No need to modify any variables in `this` since call below releases `this`.
     DequeueConnectionCallbacks(reason);
     // Do not touch `this` instance anymore; it has been destroyed in DequeueConnectionCallbacks.

src/controller/CHIPDeviceController.cpp

@@ -59,6 +59,7 @@
 #include <protocols/secure_channel/MessageCounterManager.h>
 #include <setup_payload/QRCodeSetupPayloadParser.h>
 #include <tracing/macros.h>
+#include <tracing/metric_event.h>
 
 #if CONFIG_NETWORK_LAYER_BLE
 #include <ble/Ble.h>
@@ -79,6 +80,7 @@ using namespace chip::Transport;
 using namespace chip::Credentials;
 using namespace chip::app::Clusters;
 using namespace chip::Crypto;
+using namespace chip::Tracing;
 
 namespace chip {
 namespace Controller {
@@ -666,16 +668,20 @@ CHIP_ERROR DeviceCommissioner::PairDevice(NodeId remoteDeviceId, const char * se
 CHIP_ERROR DeviceCommissioner::PairDevice(NodeId remoteDeviceId, RendezvousParameters & params)
 {
     MATTER_TRACE_SCOPE("PairDevice", "DeviceCommissioner");
-    ReturnErrorOnFailure(EstablishPASEConnection(remoteDeviceId, params));
-    return Commission(remoteDeviceId);
+    ReturnErrorOnFailureWithMetric(kMetricDeviceCommissionerCommission, EstablishPASEConnection(remoteDeviceId, params));
+    auto errorCode = Commission(remoteDeviceId);
+    VerifyOrDoWithMetric(kMetricDeviceCommissionerCommission, CHIP_NO_ERROR == errorCode, errorCode);
+    return errorCode;
 }
 
 CHIP_ERROR DeviceCommissioner::PairDevice(NodeId remoteDeviceId, RendezvousParameters & rendezvousParams,
                                           CommissioningParameters & commissioningParams)
 {
     MATTER_TRACE_SCOPE("PairDevice", "DeviceCommissioner");
-    ReturnErrorOnFailure(EstablishPASEConnection(remoteDeviceId, rendezvousParams));
-    return Commission(remoteDeviceId, commissioningParams);
+    ReturnErrorOnFailureWithMetric(kMetricDeviceCommissionerCommission, EstablishPASEConnection(remoteDeviceId, rendezvousParams));
+    auto errorCode = Commission(remoteDeviceId, commissioningParams);
+    VerifyOrDoWithMetric(kMetricDeviceCommissionerCommission, CHIP_NO_ERROR == errorCode, errorCode);
+    return errorCode;
 }
 
 CHIP_ERROR DeviceCommissioner::EstablishPASEConnection(NodeId remoteDeviceId, const char * setUpCode, DiscoveryType discoveryType,
@@ -689,6 +695,8 @@ CHIP_ERROR DeviceCommissioner::EstablishPASEConnection(NodeId remoteDeviceId, co
 CHIP_ERROR DeviceCommissioner::EstablishPASEConnection(NodeId remoteDeviceId, RendezvousParameters & params)
 {
     MATTER_TRACE_SCOPE("EstablishPASEConnection", "DeviceCommissioner");
+    MATTER_LOG_METRIC_BEGIN(kMetricDeviceCommissionerPASESession);
+
     CHIP_ERROR err                     = CHIP_NO_ERROR;
     CommissioneeDeviceProxy * device   = nullptr;
     CommissioneeDeviceProxy * current  = nullptr;
@@ -736,6 +744,7 @@ CHIP_ERROR DeviceCommissioner::EstablishPASEConnection(NodeId remoteDeviceId, Re
                     // We already have an open secure session to this device, call the callback immediately and early return.
                     mPairingDelegate->OnPairingComplete(CHIP_NO_ERROR);
                 }
+                MATTER_LOG_METRIC_END(kMetricDeviceCommissionerPASESession, CHIP_NO_ERROR);
                 return CHIP_NO_ERROR;
             }
             if (current->IsSessionSetupInProgress())
@@ -818,6 +827,7 @@ CHIP_ERROR DeviceCommissioner::EstablishPASEConnection(NodeId remoteDeviceId, Re
         {
             ReleaseCommissioneeDevice(device);
         }
+        MATTER_LOG_METRIC_END(kMetricDeviceCommissionerPASESession, err);
     }
 
     return err;
@@ -869,8 +879,10 @@ CHIP_ERROR DeviceCommissioner::Commission(NodeId remoteDeviceId, CommissioningPa
         ChipLogError(Controller, "No default commissioner is specified");
         return CHIP_ERROR_INCORRECT_STATE;
     }
-    ReturnErrorOnFailure(mDefaultCommissioner->SetCommissioningParameters(params));
-    return Commission(remoteDeviceId);
+    ReturnErrorOnFailureWithMetric(kMetricDeviceCommissionerCommission, mDefaultCommissioner->SetCommissioningParameters(params));
+    auto errorCode = Commission(remoteDeviceId);
+    VerifyOrDoWithMetric(kMetricDeviceCommissionerCommission, CHIP_NO_ERROR == errorCode, errorCode);
+    return errorCode;
 }
 
 CHIP_ERROR DeviceCommissioner::Commission(NodeId remoteDeviceId)
@@ -908,6 +920,7 @@ CHIP_ERROR DeviceCommissioner::Commission(NodeId remoteDeviceId)
     mDefaultCommissioner->SetOperationalCredentialsDelegate(mOperationalCredentialsDelegate);
     if (device->IsSecureConnected())
     {
+        MATTER_LOG_METRIC_BEGIN(kMetricDeviceCommissionerCommission);
         mDefaultCommissioner->StartCommissioning(this, device);
     }
     else
@@ -1058,6 +1071,8 @@ void DeviceCommissioner::RendezvousCleanup(CHIP_ERROR status)
 
 void DeviceCommissioner::OnSessionEstablishmentError(CHIP_ERROR err)
 {
+    MATTER_LOG_METRIC_END(kMetricDeviceCommissionerPASESession, err);
+
     if (mPairingDelegate != nullptr)
     {
         mPairingDelegate->OnStatusUpdate(DevicePairingDelegate::SecurePairingFailed);
@@ -1086,6 +1101,7 @@ void DeviceCommissioner::OnSessionEstablished(const SessionHandle & session)
 
     ChipLogDetail(Controller, "Remote device completed SPAKE2+ handshake");
 
+    MATTER_LOG_METRIC_END(kMetricDeviceCommissionerPASESession, CHIP_NO_ERROR);
     if (mPairingDelegate != nullptr)
     {
         mPairingDelegate->OnPairingComplete(CHIP_NO_ERROR);
@@ -1094,6 +1110,7 @@ void DeviceCommissioner::OnSessionEstablished(const SessionHandle & session)
     if (mRunCommissioningAfterConnection)
     {
         mRunCommissioningAfterConnection = false;
+        MATTER_LOG_METRIC_BEGIN(kMetricDeviceCommissionerCommission);
         mDefaultCommissioner->StartCommissioning(this, device);
     }
 }
@@ -1916,6 +1933,8 @@ void DeviceCommissioner::CleanupDoneAfterError()
 
 void DeviceCommissioner::SendCommissioningCompleteCallbacks(NodeId nodeId, const CompletionStatus & completionStatus)
 {
+    MATTER_LOG_METRIC_END(kMetricDeviceCommissionerCommission, completionStatus.err);
+
     ChipLogProgress(Controller, "Commissioning complete for node ID 0x" ChipLogFormatX64 ": %s", ChipLogValueX64(nodeId),
                     (completionStatus.err == CHIP_NO_ERROR ? "success" : completionStatus.err.AsString()));
     mCommissioningStage = CommissioningStage::kSecurePairing;
@@ -1924,6 +1943,7 @@ void DeviceCommissioner::SendCommissioningCompleteCallbacks(NodeId nodeId, const
     {
         return;
     }
+
     mPairingDelegate->OnCommissioningComplete(nodeId, completionStatus.err);
     PeerId peerId(GetCompressedFabricId(), nodeId);
     if (completionStatus.err == CHIP_NO_ERROR)
@@ -1943,6 +1963,7 @@ void DeviceCommissioner::CommissioningStageComplete(CHIP_ERROR err, Commissionin
 {
     // Once this stage is complete, reset mDeviceBeingCommissioned - this will be reset when the delegate calls the next step.
     MATTER_TRACE_SCOPE("CommissioningStageComplete", "DeviceCommissioner");
+    MATTER_LOG_METRIC_END(MetricKeyForCommissioningStage(mCommissioningStage), err);
     VerifyOrDie(mDeviceBeingCommissioned);
 
     NodeId nodeId            = mDeviceBeingCommissioned->GetDeviceId();
@@ -1978,6 +1999,7 @@ void DeviceCommissioner::OnDeviceConnectedFn(void * context, Messaging::Exchange
                                              const SessionHandle & sessionHandle)
 {
     // CASE session established.
+    MATTER_LOG_METRIC_END(kMetricDeviceCommissioningOperationalSetup, CHIP_NO_ERROR);
     DeviceCommissioner * commissioner = static_cast<DeviceCommissioner *>(context);
     VerifyOrDie(commissioner->mCommissioningStage == CommissioningStage::kFindOperationalForStayActive ||
                 commissioner->mCommissioningStage == CommissioningStage::kFindOperationalForCommissioningComplete);
@@ -1992,6 +2014,7 @@ void DeviceCommissioner::OnDeviceConnectedFn(void * context, Messaging::Exchange
 void DeviceCommissioner::OnDeviceConnectionFailureFn(void * context, const ScopedNodeId & peerId, CHIP_ERROR error)
 {
     // CASE session establishment failed.
+    MATTER_LOG_METRIC_END(kMetricDeviceCommissioningOperationalSetup, error);
     DeviceCommissioner * commissioner = static_cast<DeviceCommissioner *>(context);
     VerifyOrDie(commissioner->mCommissioningStage == CommissioningStage::kFindOperationalForStayActive ||
                 commissioner->mCommissioningStage == CommissioningStage::kFindOperationalForCommissioningComplete);
@@ -2748,7 +2771,11 @@ void DeviceCommissioner::SendCommissioningReadRequest(DeviceProxy * proxy, Optio
 void DeviceCommissioner::PerformCommissioningStep(DeviceProxy * proxy, CommissioningStage step, CommissioningParameters & params,
                                                   CommissioningDelegate * delegate, EndpointId endpoint,
                                                   Optional<System::Clock::Timeout> timeout)
+
 {
+    MATTER_LOG_METRIC(kMetricDeviceCommissionerCommissionStage, step);
+    MATTER_LOG_METRIC_BEGIN(MetricKeyForCommissioningStage(step));
+
     if (params.GetCompletionStatus().err == CHIP_NO_ERROR)
     {
         ChipLogProgress(Controller, "Performing next commissioning step '%s'", StageToString(step));
@@ -3385,6 +3412,7 @@ void DeviceCommissioner::PerformCommissioningStep(DeviceProxy * proxy, Commissio
     case CommissioningStage::kFindOperationalForCommissioningComplete: {
         // If there is an error, CommissioningStageComplete will be called from OnDeviceConnectionFailureFn.
         auto scopedPeerId = GetPeerScopedId(proxy->GetDeviceId());
+        MATTER_LOG_METRIC_BEGIN(kMetricDeviceCommissioningOperationalSetup);
         mSystemState->CASESessionMgr()->FindOrEstablishSession(scopedPeerId, &mOnDeviceConnectedCallback,
                                                                &mOnDeviceConnectionFailureCallback
 #if CHIP_DEVICE_CONFIG_ENABLE_AUTOMATIC_CASE_RETRIES

src/controller/CommissioningDelegate.cpp

@@ -141,5 +141,124 @@ const char * StageToString(CommissioningStage stage)
     }
 }
 
+#if MATTER_TRACING_ENABLED
+const char * MetricKeyForCommissioningStage(CommissioningStage stage)
+{
+    switch (stage)
+    {
+    case kError:
+        return "core_commissioning_stage_error";
+
+    case kSecurePairing:
+        return "core_commissioning_stage_secure_pairing";
+
+    case kReadCommissioningInfo:
+        return "core_commissioning_stage_read_commissioning_info";
+
+    case kReadCommissioningInfo2:
+        return "core_commissioning_stage_read_commissioning_info2";
+
+    case kArmFailsafe:
+        return "core_commissioning_stage_arm_failsafe";
+
+    case kScanNetworks:
+        return "core_commissioning_stage_scan_networks";
+
+    case kConfigRegulatory:
+        return "core_commissioning_stage_config_regulatory";
+
+    case kConfigureUTCTime:
+        return "core_commissioning_stage_configure_utc_time";
+
+    case kConfigureTimeZone:
+        return "core_commissioning_stage_configure_timezone";
+
+    case kConfigureDSTOffset:
+        return "core_commissioning_stage_configure_dst_offset";
+
+    case kConfigureDefaultNTP:
+        return "core_commissioning_stage_configure_default_ntp";
+
+    case kSendPAICertificateRequest:
+        return "core_commissioning_stage_send_pai_certificate_request";
+
+    case kSendDACCertificateRequest:
+        return "core_commissioning_stage_send_dac_certificate_request";
+
+    case kSendAttestationRequest:
+        return "core_commissioning_stage_send_attestation_request";
+
+    case kAttestationVerification:
+        return "core_commissioning_stage_attestation_verification";
+
+    case kSendOpCertSigningRequest:
+        return "core_commissioning_stage_opcert_signing_request";
+
+    case kValidateCSR:
+        return "core_commissioning_stage_validate_csr";
+
+    case kGenerateNOCChain:
+        return "core_commissioning_stage_generate_noc_chain";
+
+    case kSendTrustedRootCert:
+        return "core_commissioning_stage_send_trusted_root_cert";
+
+    case kSendNOC:
+        return "core_commissioning_stage_send_noc";
+
+    case kConfigureTrustedTimeSource:
+        return "core_commissioning_stage_configure_trusted_time_source";
+
+    case kICDGetRegistrationInfo:
+        return "core_commissioning_stage_icd_get_registration_info";
+
+    case kICDRegistration:
+        return "core_commissioning_stage_icd_registration";
+
+    case kWiFiNetworkSetup:
+        return "core_commissioning_stage_wifi_network_setup";
+
+    case kThreadNetworkSetup:
+        return "core_commissioning_stage_thread_network_setup";
+
+    case kFailsafeBeforeWiFiEnable:
+        return "core_commissioning_stage_failsafe_before_wifi_enable";
+
+    case kFailsafeBeforeThreadEnable:
+        return "core_commissioning_stage_failsafe_before_thread_enable";
+
+    case kWiFiNetworkEnable:
+        return "core_commissioning_stage_wifi_network_enable";
+
+    case kThreadNetworkEnable:
+        return "core_commissioning_stage_thread_network_enable";
+
+    case kEvictPreviousCaseSessions:
+        return "core_commissioning_stage_evict_previous_case_sessions";
+
+    case kFindOperationalForStayActive:
+        return "core_commissioning_stage_find_operational_for_stay_active";
+
+    case kFindOperationalForCommissioningComplete:
+        return "core_commissioning_stage_find_operational_for_commissioning_complete";
+
+    case kICDSendStayActive:
+        return "core_commissioning_stage_icd_send_stay_active";
+
+    case kSendComplete:
+        return "core_commissioning_stage_send_complete";
+
+    case kCleanup:
+        return "core_commissioning_stage_cleanup";
+
+    case kNeedsNetworkCreds:
+        return "core_commissioning_stage_need_network_creds";
+
+    default:
+        return "core_commissioning_stage_unknown";
+    }
+}
+#endif
+
 } // namespace Controller
 } // namespace chip