From 443bb9c775a09c28b3b6a15bfd2bf7e91cfec5ad Mon Sep 17 00:00:00 2001 From: Anush Nadathur Date: Fri, 17 May 2024 14:54:38 -0700 Subject: [PATCH] [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 * Resytler fixes --------- Co-authored-by: Boris Zbarsky --- src/app/OperationalSessionSetup.cpp | 22 ++++ src/controller/CHIPDeviceController.cpp | 40 +++++- src/controller/CommissioningDelegate.cpp | 119 ++++++++++++++++++ src/controller/CommissioningDelegate.h | 5 + src/controller/SetUpCodePairer.cpp | 25 +++- .../Framework/CHIP/MTRDeviceController.mm | 52 +++++--- src/tracing/metric_keys.h | 23 ++++ src/tracing/metric_macros.h | 7 +- src/tracing/tests/TestMetricEvents.cpp | 16 +-- 9 files changed, 268 insertions(+), 41 deletions(-) diff --git a/src/app/OperationalSessionSetup.cpp b/src/app/OperationalSessionSetup.cpp index 9d91b7b573a59f..5733a423702226 100644 --- a/src/app/OperationalSessionSetup.cpp +++ b/src/app/OperationalSessionSetup.cpp @@ -38,11 +38,13 @@ #include #include #include +#include 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. diff --git a/src/controller/CHIPDeviceController.cpp b/src/controller/CHIPDeviceController.cpp index 910c0b21040c96..1381ed3381a649 100644 --- a/src/controller/CHIPDeviceController.cpp +++ b/src/controller/CHIPDeviceController.cpp @@ -59,6 +59,7 @@ #include #include #include +#include #if CONFIG_NETWORK_LAYER_BLE #include @@ -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(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(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 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 diff --git a/src/controller/CommissioningDelegate.cpp b/src/controller/CommissioningDelegate.cpp index b3e3b6ca2ac754..30f469932a800a 100644 --- a/src/controller/CommissioningDelegate.cpp +++ b/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 diff --git a/src/controller/CommissioningDelegate.h b/src/controller/CommissioningDelegate.h index e79ad1d67c4bcf..57d6a0c9a8da53 100644 --- a/src/controller/CommissioningDelegate.h +++ b/src/controller/CommissioningDelegate.h @@ -24,6 +24,7 @@ #include #include #include +#include #include namespace chip { @@ -89,6 +90,10 @@ enum class ICDRegistrationStrategy : uint8_t const char * StageToString(CommissioningStage stage); +#if MATTER_TRACING_ENABLED +const char * MetricKeyForCommissioningStage(CommissioningStage stage); +#endif + struct WiFiCredentials { ByteSpan ssid; diff --git a/src/controller/SetUpCodePairer.cpp b/src/controller/SetUpCodePairer.cpp index 4eb107a3711c10..8ebf78a3fc545e 100644 --- a/src/controller/SetUpCodePairer.cpp +++ b/src/controller/SetUpCodePairer.cpp @@ -30,9 +30,12 @@ #include #include #include +#include constexpr uint32_t kDeviceDiscoveredTimeout = CHIP_CONFIG_SETUP_CODE_PAIRER_DISCOVERY_TIMEOUT_SECS * chip::kMillisecondsPerSecond; +using namespace chip::Tracing; + namespace chip { namespace Controller { @@ -59,15 +62,16 @@ CHIP_ERROR GetPayload(const char * setUpCode, SetupPayload & payload) CHIP_ERROR SetUpCodePairer::PairDevice(NodeId remoteId, const char * setUpCode, SetupCodePairerBehaviour commission, DiscoveryType discoveryType, Optional resolutionData) { - VerifyOrReturnError(mSystemLayer != nullptr, CHIP_ERROR_INCORRECT_STATE); - VerifyOrReturnError(remoteId != kUndefinedNodeId, CHIP_ERROR_INVALID_ARGUMENT); + VerifyOrReturnErrorWithMetric(kMetricSetupCodePairerPairDevice, mSystemLayer != nullptr, CHIP_ERROR_INCORRECT_STATE); + VerifyOrReturnErrorWithMetric(kMetricSetupCodePairerPairDevice, remoteId != kUndefinedNodeId, CHIP_ERROR_INVALID_ARGUMENT); SetupPayload payload; ReturnErrorOnFailure(GetPayload(setUpCode, payload)); if (resolutionData.HasValue()) { - VerifyOrReturnError(discoveryType != DiscoveryType::kAll, CHIP_ERROR_INVALID_ARGUMENT); + VerifyOrReturnErrorWithMetric(kMetricSetupCodePairerPairDevice, discoveryType != DiscoveryType::kAll, + CHIP_ERROR_INVALID_ARGUMENT); if (mRemoteId == remoteId && mSetUpPINCode == payload.setUpPINCode && mConnectionType == commission && mDiscoveryType == discoveryType) { @@ -89,10 +93,16 @@ CHIP_ERROR SetUpCodePairer::PairDevice(NodeId remoteId, const char * setUpCode, return CHIP_NO_ERROR; } - ReturnErrorOnFailure(Connect(payload)); - return mSystemLayer->StartTimer(System::Clock::Milliseconds32(kDeviceDiscoveredTimeout), OnDeviceDiscoveredTimeoutCallback, - this); + ReturnErrorOnFailureWithMetric(kMetricSetupCodePairerPairDevice, Connect(payload)); + auto errorCode = + mSystemLayer->StartTimer(System::Clock::Milliseconds32(kDeviceDiscoveredTimeout), OnDeviceDiscoveredTimeoutCallback, this); + if (CHIP_NO_ERROR == errorCode) + { + MATTER_LOG_METRIC_BEGIN(kMetricSetupCodePairerPairDevice); + } + return errorCode; } + CHIP_ERROR SetUpCodePairer::Connect(SetupPayload & payload) { CHIP_ERROR err = CHIP_NO_ERROR; @@ -536,6 +546,7 @@ void SetUpCodePairer::OnPairingComplete(CHIP_ERROR error) ChipLogProgress(Controller, "PASE session established with commissionee. Stopping discovery."); ResetDiscoveryState(); mRemoteId = kUndefinedNodeId; + MATTER_LOG_METRIC_END(kMetricSetupCodePairerPairDevice, error); if (pairingDelegate != nullptr) { pairingDelegate->OnPairingComplete(error); @@ -568,6 +579,7 @@ void SetUpCodePairer::OnPairingComplete(CHIP_ERROR error) return; } + MATTER_LOG_METRIC_END(kMetricSetupCodePairerPairDevice, error); if (pairingDelegate != nullptr) { pairingDelegate->OnPairingComplete(error); @@ -608,6 +620,7 @@ void SetUpCodePairer::OnDeviceDiscoveredTimeoutCallback(System::Layer * layer, v { err = CHIP_ERROR_TIMEOUT; } + MATTER_LOG_METRIC_END(kMetricSetupCodePairerPairDevice, err); pairer->mCommissioner->OnSessionEstablishmentError(err); } } diff --git a/src/darwin/Framework/CHIP/MTRDeviceController.mm b/src/darwin/Framework/CHIP/MTRDeviceController.mm index 9c4b0a47059a80..16b4d7f385e3aa 100644 --- a/src/darwin/Framework/CHIP/MTRDeviceController.mm +++ b/src/darwin/Framework/CHIP/MTRDeviceController.mm @@ -627,12 +627,6 @@ 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 @@ -667,9 +661,13 @@ - (BOOL)setupCommissioningSessionWithPayload:(MTRSetupPayload *)payload chip::NodeId nodeId = [newNodeID unsignedLongLongValue]; self->_operationalCredentialsDelegate->SetDeviceID(nodeId); - [self preparePASESessionMetric:nodeId]; + MATTER_LOG_METRIC_BEGIN(kMetricSetupPASESession); errorCode = self->_cppCommissioner->EstablishPASEConnection(nodeId, [pairingCode UTF8String]); - VerifyOrDo(errorCode != CHIP_NO_ERROR, MATTER_LOG_METRIC_END(kMetricSetupPASESession, errorCode)); + if (CHIP_NO_ERROR == errorCode) { + self->_deviceControllerDelegateBridge->SetDeviceNodeID(nodeId); + } else { + MATTER_LOG_METRIC_END(kMetricSetupPASESession, errorCode); + } return ![MTRDeviceController checkForError:errorCode logMsg:kErrorPairDevice error:error]; }; @@ -711,9 +709,13 @@ - (BOOL)setupCommissioningSessionWithDiscoveredDevice:(MTRCommissionableBrowserR auto pinCode = static_cast(payload.setupPasscode.unsignedLongValue); params.Value().SetSetupPINCode(pinCode); - [self preparePASESessionMetric:nodeId]; + MATTER_LOG_METRIC_BEGIN(kMetricSetupPASESession); errorCode = self->_cppCommissioner->EstablishPASEConnection(nodeId, params.Value()); - VerifyOrDo(errorCode != CHIP_NO_ERROR, MATTER_LOG_METRIC_END(kMetricSetupPASESession, errorCode)); + if (CHIP_NO_ERROR == errorCode) { + self->_deviceControllerDelegateBridge->SetDeviceNodeID(nodeId); + } else { + 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. @@ -732,10 +734,12 @@ - (BOOL)setupCommissioningSessionWithDiscoveredDevice:(MTRCommissionableBrowserR continue; } - [self preparePASESessionMetric:nodeId]; + MATTER_LOG_METRIC_BEGIN(kMetricSetupPASESession); errorCode = self->_cppCommissioner->EstablishPASEConnection( nodeId, [pairingCode UTF8String], chip::Controller::DiscoveryType::kDiscoveryNetworkOnly, resolutionData); - if (CHIP_NO_ERROR != errorCode) { + if (CHIP_NO_ERROR == errorCode) { + self->_deviceControllerDelegateBridge->SetDeviceNodeID(nodeId); + } else { MATTER_LOG_METRIC_END(kMetricSetupPASESession, errorCode); break; } @@ -1710,9 +1714,13 @@ - (BOOL)pairDevice:(uint64_t)deviceID self->_operationalCredentialsDelegate->SetDeviceID(deviceID); - [self preparePASESessionMetric:deviceID]; + MATTER_LOG_METRIC_BEGIN(kMetricSetupPASESession); errorCode = self->_cppCommissioner->EstablishPASEConnection(deviceID, manualPairingCode.c_str()); - VerifyOrDo(errorCode != CHIP_NO_ERROR, MATTER_LOG_METRIC_END(kMetricSetupPASESession, errorCode)); + if (CHIP_NO_ERROR == errorCode) { + self->_deviceControllerDelegateBridge->SetDeviceNodeID(deviceID); + } else { + MATTER_LOG_METRIC_END(kMetricSetupPASESession, errorCode); + } return ![MTRDeviceController checkForError:errorCode logMsg:kErrorPairDevice error:error]; }; @@ -1751,9 +1759,13 @@ - (BOOL)pairDevice:(uint64_t)deviceID auto params = chip::RendezvousParameters().SetSetupPINCode(setupPINCode).SetPeerAddress(peerAddress); - [self preparePASESessionMetric:deviceID]; + MATTER_LOG_METRIC_BEGIN(kMetricSetupPASESession); errorCode = self->_cppCommissioner->EstablishPASEConnection(deviceID, params); - VerifyOrDo(errorCode != CHIP_NO_ERROR, MATTER_LOG_METRIC_END(kMetricSetupPASESession, errorCode)); + if (CHIP_NO_ERROR == errorCode) { + self->_deviceControllerDelegateBridge->SetDeviceNodeID(deviceID); + } else { + MATTER_LOG_METRIC_END(kMetricSetupPASESession, errorCode); + } return ![MTRDeviceController checkForError:errorCode logMsg:kErrorPairDevice error:error]; }; @@ -1783,9 +1795,13 @@ - (BOOL)pairDevice:(uint64_t)deviceID onboardingPayload:(NSString *)onboardingPa self->_operationalCredentialsDelegate->SetDeviceID(deviceID); - [self preparePASESessionMetric:deviceID]; + MATTER_LOG_METRIC_BEGIN(kMetricSetupPASESession); errorCode = self->_cppCommissioner->EstablishPASEConnection(deviceID, [onboardingPayload UTF8String]); - VerifyOrDo(errorCode != CHIP_NO_ERROR, MATTER_LOG_METRIC_END(kMetricSetupPASESession, errorCode)); + if (CHIP_NO_ERROR == errorCode) { + self->_deviceControllerDelegateBridge->SetDeviceNodeID(deviceID); + } else { + MATTER_LOG_METRIC_END(kMetricSetupPASESession, errorCode); + } return ![MTRDeviceController checkForError:errorCode logMsg:kErrorPairDevice error:error]; }; diff --git a/src/tracing/metric_keys.h b/src/tracing/metric_keys.h index 2f80af9b4a1441..001e9c8036bd27 100644 --- a/src/tracing/metric_keys.h +++ b/src/tracing/metric_keys.h @@ -31,5 +31,28 @@ typedef const char * MetricKey; */ constexpr MetricKey kMetricWiFiRSSI = "wifi_rssi"; +// Overall PASE session est in device commissioner +constexpr MetricKey kMetricDeviceCommissionerPASESession = "core_dcm_pase_session"; + +// Overall commissioning into a fabric +constexpr MetricKey kMetricDeviceCommissionerCommission = "core_dcm_commission_device"; + +constexpr MetricKey kMetricDeviceCommissionerCommissionStage = "core_dcm_commission_stage"; + +// Setup Code Pairer +constexpr MetricKey kMetricSetupCodePairerPairDevice = "core_setup_code_pairer_pair_dev"; + +// Commissioning Operational Setup (Discovery + CASE) +constexpr MetricKey kMetricDeviceCommissioningOperationalSetup = "core_dcm_operational_setup"; + +// Operational Discovery +constexpr MetricKey kMetricDeviceOperationalDiscovery = "core_dev_operational_discovery"; + +// Operational Discovery Attempt Count +constexpr MetricKey kMetricDeviceOperationalDiscoveryAttemptCount = "core_dev_operational_discovery_attempt_ctr"; + +// CASE Session +constexpr MetricKey kMetricDeviceCASESession = "core_dev_case_session"; + } // namespace Tracing } // namespace chip diff --git a/src/tracing/metric_macros.h b/src/tracing/metric_macros.h index 26dde8cd3230a0..3d00e7d9d9677b 100644 --- a/src/tracing/metric_macros.h +++ b/src/tracing/metric_macros.h @@ -434,14 +434,15 @@ * @param[in] kMetricKey Metric key for the metric event to be emitted. * Value of the metric is set to false. * @param[in] expr A Boolean expression to be evaluated. + * @param[in] code Error code to emit as part of the metric. * @param[in] ... Statements to execute. */ -#define VerifyOrDoWithMetric(kMetricKey, expr, ...) \ +#define VerifyOrDoWithMetric(kMetricKey, expr, code, ...) \ do \ { \ if (!(expr)) \ { \ - MATTER_LOG_METRIC(kMetricKey, false); \ + MATTER_LOG_METRIC(kMetricKey, code); \ __VA_ARGS__; \ } \ } while (false) @@ -592,7 +593,7 @@ #define LogErrorOnFailureWithMetric(kMetricKey, expr) LogErrorOnFailure(expr) -#define VerifyOrDoWithMetric(kMetricKey, expr, ...) VerifyOrDo(expr, ##__VA_ARGS__) +#define VerifyOrDoWithMetric(kMetricKey, expr, code, ...) VerifyOrDo(expr, ##__VA_ARGS__) //////////////////////////////////////////////////////////////////////////////////////////////////////////////// // Map all MATTER_LOG_METRIC_XYZ macros to noops diff --git a/src/tracing/tests/TestMetricEvents.cpp b/src/tracing/tests/TestMetricEvents.cpp index 916a002d9f78b9..17e4cd69797177 100644 --- a/src/tracing/tests/TestMetricEvents.cpp +++ b/src/tracing/tests/TestMetricEvents.cpp @@ -597,17 +597,17 @@ TEST(TestMetricEvents, TestVerifyOrDoWithMetric) MetricEventBackend backend; ScopedRegistration scope(backend); - VerifyOrDoWithMetric("event0", DoubleOf(2) == 5); - VerifyOrDoWithMetric("event1", DoubleOf(3) == 6); - VerifyOrDoWithMetric("event2", DoubleOf(4) == 7, MATTER_LOG_METRIC("event4", 10)); - VerifyOrDoWithMetric("event3", DoubleOf(5) == 8); - VerifyOrDoWithMetric("event5", DoubleOf(6) == 12); + VerifyOrDoWithMetric("event0", DoubleOf(2) == 5, 11); + VerifyOrDoWithMetric("event1", DoubleOf(3) == 6, 12); + VerifyOrDoWithMetric("event2", DoubleOf(4) == 7, CHIP_ERROR_BAD_REQUEST, MATTER_LOG_METRIC("event4", 10)); + VerifyOrDoWithMetric("event3", DoubleOf(5) == 8, 13); + VerifyOrDoWithMetric("event5", DoubleOf(6) == 12, 14); std::vector expected = { - MetricEvent(MetricEvent::Type::kInstantEvent, "event0", false), - MetricEvent(MetricEvent::Type::kInstantEvent, "event2", false), + MetricEvent(MetricEvent::Type::kInstantEvent, "event0", 11), + MetricEvent(MetricEvent::Type::kInstantEvent, "event2", CHIP_ERROR_BAD_REQUEST), MetricEvent(MetricEvent::Type::kInstantEvent, "event4", 10), - MetricEvent(MetricEvent::Type::kInstantEvent, "event3", false), + MetricEvent(MetricEvent::Type::kInstantEvent, "event3", 13), }; EXPECT_EQ(backend.GetMetricEvents().size(), expected.size());