From ae4460a2f5c4cd4517a75bd55c091ab81dd6f45e Mon Sep 17 00:00:00 2001 From: Anush Nadathur Date: Wed, 3 Apr 2024 13:36:22 -0700 Subject: [PATCH 1/6] [Metrics] Metrics in core commissioning phase - Added metrics tracing in core parts of the commissionning flow: - PASE - OperationalSessionSetup - Different stages of commissioning --- src/app/OperationalSessionSetup.cpp | 16 +++ src/controller/AutoCommissioner.cpp | 2 + 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/protocols/secure_channel/CASESession.cpp | 1 + src/tracing/metric_keys.h | 23 ++++ src/tracing/metric_macros.h | 7 +- src/tracing/tests/TestMetricEvents.cpp | 16 +-- 11 files changed, 265 insertions(+), 41 deletions(-) diff --git a/src/app/OperationalSessionSetup.cpp b/src/app/OperationalSessionSetup.cpp index 9d91b7b573a59f..67700454e65d40 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 { @@ -246,6 +248,8 @@ void OperationalSessionSetup::UpdateDeviceData(const Transport::PeerAddress & ad return; } + MATTER_LOG_METRIC_END(kMetricDeviceOperationalDiscovery, CHIP_NO_ERROR); + CHIP_ERROR err = EstablishConnection(config); LogErrorOnFailure(err); if (err == CHIP_NO_ERROR) @@ -305,9 +309,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 +509,7 @@ void OperationalSessionSetup::OnSessionEstablishmentError(CHIP_ERROR error, Sess #endif // CHIP_DEVICE_CONFIG_ENABLE_AUTOMATIC_CASE_RETRIES } + MATTER_LOG_METRIC_END(kMetricDeviceCASESession, error); DequeueConnectionCallbacks(error, stage); // Do not touch `this` instance anymore; it has been destroyed in DequeueConnectionCallbacks. } @@ -521,6 +528,8 @@ void OperationalSessionSetup::OnSessionEstablished(const SessionHandle & session VerifyOrReturn(mState == State::Connecting, ChipLogError(Discovery, "OnSessionEstablished was called while we were not connecting")); + 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 +600,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 +615,8 @@ CHIP_ERROR OperationalSessionSetup::LookupPeerAddress() return CHIP_NO_ERROR; } + MATTER_LOG_METRIC_BEGIN(kMetricDeviceOperationalDiscovery); + auto const * fabricInfo = mInitParams.fabricTable->FindFabricWithIndex(mPeerId.GetFabricIndex()); VerifyOrReturnError(fabricInfo != nullptr, CHIP_ERROR_INVALID_FABRIC_INDEX); @@ -676,6 +688,8 @@ void OperationalSessionSetup::OnNodeAddressResolutionFailed(const PeerId & peerI --mAttemptsDone; } + MATTER_LOG_METRIC(kMetricDeviceOperationalDiscoveryAttemptCount, mAttemptsDone); + CHIP_ERROR err = LookupPeerAddress(); if (err == CHIP_NO_ERROR) { @@ -690,6 +704,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/AutoCommissioner.cpp b/src/controller/AutoCommissioner.cpp index 5b37988a491260..8a63389f440ba1 100644 --- a/src/controller/AutoCommissioner.cpp +++ b/src/controller/AutoCommissioner.cpp @@ -24,12 +24,14 @@ #include #include #include +#include namespace chip { namespace Controller { using namespace chip::app::Clusters; using namespace chip::Crypto; +using namespace chip::Tracing; using chip::app::DataModel::MakeNullable; using chip::app::DataModel::NullNullable; diff --git a/src/controller/CHIPDeviceController.cpp b/src/controller/CHIPDeviceController.cpp index 910c0b21040c96..e609f01de068e3 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(kMetricDeviceOperationalSetup, 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(kMetricDeviceOperationalSetup, 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(kMetricDeviceOperationalSetup); 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..cd47eb0aaa842a 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_cm_stg_error"; + + case kSecurePairing: + return "core_cm_stg_secure_pairing"; + + case kReadCommissioningInfo: + return "core_cm_stg_rd_comm_info"; + + case kReadCommissioningInfo2: + return "core_cm_stg_rd_comm_info2"; + + case kArmFailsafe: + return "core_cm_stg_afs"; + + case kScanNetworks: + return "core_cm_stg_scn_nws"; + + case kConfigRegulatory: + return "core_cm_stg_cfg_reg"; + + case kConfigureUTCTime: + return "core_cm_stg_cfg_utc"; + + case kConfigureTimeZone: + return "core_cm_stg_cfg_tmz"; + + case kConfigureDSTOffset: + return "core_cm_stg_cfg_dst_off"; + + case kConfigureDefaultNTP: + return "core_cm_stg_cfg_ntp"; + + case kSendPAICertificateRequest: + return "core_cm_stg_csr_req"; + + case kSendDACCertificateRequest: + return "core_cm_stg_dac_req"; + + case kSendAttestationRequest: + return "core_cm_stg_att_req"; + + case kAttestationVerification: + return "core_cm_stg_att_ver"; + + case kSendOpCertSigningRequest: + return "core_cm_stg_opcrt_csr"; + + case kValidateCSR: + return "core_cm_stg_val_csr"; + + case kGenerateNOCChain: + return "core_cm_stg_gen_noc"; + + case kSendTrustedRootCert: + return "core_cm_stg_trust_rca"; + + case kSendNOC: + return "core_cm_stg_snd_noc"; + + case kConfigureTrustedTimeSource: + return "core_cm_stg_cfg_tms"; + + case kICDGetRegistrationInfo: + return "core_cm_stg_icd_reg_info"; + + case kICDRegistration: + return "core_cm_stg_icd_reg"; + + case kWiFiNetworkSetup: + return "core_cm_stg_wifi_nw_cred"; + + case kThreadNetworkSetup: + return "core_cm_stg_thrd_nw_cred"; + + case kFailsafeBeforeWiFiEnable: + return "core_cm_stg_afs_bf_wifi"; + + case kFailsafeBeforeThreadEnable: + return "core_cm_stg_afs_bf_thrd"; + + case kWiFiNetworkEnable: + return "core_cm_stg_wifi_enbl"; + + case kThreadNetworkEnable: + return "core_cm_stg_thrd_enbl"; + + case kEvictPreviousCaseSessions: + return "core_cm_stg_evict_case"; + + case kFindOperationalForStayActive: + return "core_cm_stg_op_stay_active"; + + case kFindOperationalForCommissioningComplete: + return "core_cm_stg_op_cm_comp"; + + case kICDSendStayActive: + return "core_cm_stg_icd_stay_act"; + + case kSendComplete: + return "core_cm_stg_snd_comp"; + + case kCleanup: + return "core_cm_stg_cleanup"; + + case kNeedsNetworkCreds: + return "core_cm_stg_need_nw_creds"; + + default: + return "core_cm_stg_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 fe266c22a2fff9..e1375ceb38babe 100644 --- a/src/darwin/Framework/CHIP/MTRDeviceController.mm +++ b/src/darwin/Framework/CHIP/MTRDeviceController.mm @@ -606,12 +606,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 @@ -646,9 +640,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]; }; @@ -690,9 +688,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. @@ -711,10 +713,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; } @@ -1681,9 +1685,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]; }; @@ -1722,9 +1730,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]; }; @@ -1754,9 +1766,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/protocols/secure_channel/CASESession.cpp b/src/protocols/secure_channel/CASESession.cpp index ccc2bc2188d176..aea8d9bd3e98e6 100644 --- a/src/protocols/secure_channel/CASESession.cpp +++ b/src/protocols/secure_channel/CASESession.cpp @@ -47,6 +47,7 @@ #include #include #include +#include #include namespace { diff --git a/src/tracing/metric_keys.h b/src/tracing/metric_keys.h index 2f80af9b4a1441..f0b27e0d01b034 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"; + +constexpr MetricKey kMetricDeviceCommissionerCommissionStage = "core_ccm_commission_stage"; + +// Setup Code Pairer +constexpr MetricKey kMetricSetupCodePairerPairDevice = "core_scp_pair_dev"; + +// Operational Setup (Discovery + CASE) +constexpr MetricKey kMetricDeviceOperationalSetup = "core_dev_opr_setup"; + +// Operational Discovery +constexpr MetricKey kMetricDeviceOperationalDiscovery = "core_dev_opr_discovery"; + +// Operational Discovery Attempt Count +constexpr MetricKey kMetricDeviceOperationalDiscoveryAttemptCount = "core_dev_opdisc_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()); From 062f1655e0dad8938c261b1d598f8e8304a0eaba Mon Sep 17 00:00:00 2001 From: Anush Nadathur Date: Fri, 10 May 2024 18:19:34 -0700 Subject: [PATCH 2/6] Fixing code review comments --- src/app/OperationalSessionSetup.cpp | 7 +- src/controller/AutoCommissioner.cpp | 2 - src/controller/CHIPDeviceController.cpp | 6 +- src/controller/CommissioningDelegate.cpp | 74 ++++++++++---------- src/protocols/secure_channel/CASESession.cpp | 1 - src/tracing/metric_keys.h | 14 ++-- 6 files changed, 52 insertions(+), 52 deletions(-) diff --git a/src/app/OperationalSessionSetup.cpp b/src/app/OperationalSessionSetup.cpp index 67700454e65d40..9d429d46595936 100644 --- a/src/app/OperationalSessionSetup.cpp +++ b/src/app/OperationalSessionSetup.cpp @@ -248,8 +248,6 @@ void OperationalSessionSetup::UpdateDeviceData(const Transport::PeerAddress & ad return; } - MATTER_LOG_METRIC_END(kMetricDeviceOperationalDiscovery, CHIP_NO_ERROR); - CHIP_ERROR err = EstablishConnection(config); LogErrorOnFailure(err); if (err == CHIP_NO_ERROR) @@ -309,6 +307,9 @@ CHIP_ERROR OperationalSessionSetup::EstablishConnection(const ReliableMessagePro mCASEClient = mClientPool->Allocate(); ReturnErrorCodeIf(mCASEClient == nullptr, CHIP_ERROR_NO_MEMORY); + // Session has been established. This is when discovery is also stopped + MATTER_LOG_METRIC_END(kMetricDeviceOperationalDiscovery, CHIP_NO_ERROR); + MATTER_LOG_METRIC_BEGIN(kMetricDeviceCASESession); CHIP_ERROR err = mCASEClient->EstablishSession(mInitParams, mPeerId, mDeviceAddress, config, this); if (err != CHIP_NO_ERROR) @@ -615,6 +616,8 @@ CHIP_ERROR OperationalSessionSetup::LookupPeerAddress() return CHIP_NO_ERROR; } + // This call be called multiple times for each discovered address.The metric backend can handle this + // and always pick the earliest occurance as the start of the event. MATTER_LOG_METRIC_BEGIN(kMetricDeviceOperationalDiscovery); auto const * fabricInfo = mInitParams.fabricTable->FindFabricWithIndex(mPeerId.GetFabricIndex()); diff --git a/src/controller/AutoCommissioner.cpp b/src/controller/AutoCommissioner.cpp index 8a63389f440ba1..5b37988a491260 100644 --- a/src/controller/AutoCommissioner.cpp +++ b/src/controller/AutoCommissioner.cpp @@ -24,14 +24,12 @@ #include #include #include -#include namespace chip { namespace Controller { using namespace chip::app::Clusters; using namespace chip::Crypto; -using namespace chip::Tracing; using chip::app::DataModel::MakeNullable; using chip::app::DataModel::NullNullable; diff --git a/src/controller/CHIPDeviceController.cpp b/src/controller/CHIPDeviceController.cpp index e609f01de068e3..1381ed3381a649 100644 --- a/src/controller/CHIPDeviceController.cpp +++ b/src/controller/CHIPDeviceController.cpp @@ -1999,7 +1999,7 @@ void DeviceCommissioner::OnDeviceConnectedFn(void * context, Messaging::Exchange const SessionHandle & sessionHandle) { // CASE session established. - MATTER_LOG_METRIC_END(kMetricDeviceOperationalSetup, CHIP_NO_ERROR); + MATTER_LOG_METRIC_END(kMetricDeviceCommissioningOperationalSetup, CHIP_NO_ERROR); DeviceCommissioner * commissioner = static_cast(context); VerifyOrDie(commissioner->mCommissioningStage == CommissioningStage::kFindOperationalForStayActive || commissioner->mCommissioningStage == CommissioningStage::kFindOperationalForCommissioningComplete); @@ -2014,7 +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(kMetricDeviceOperationalSetup, error); + MATTER_LOG_METRIC_END(kMetricDeviceCommissioningOperationalSetup, error); DeviceCommissioner * commissioner = static_cast(context); VerifyOrDie(commissioner->mCommissioningStage == CommissioningStage::kFindOperationalForStayActive || commissioner->mCommissioningStage == CommissioningStage::kFindOperationalForCommissioningComplete); @@ -3412,7 +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(kMetricDeviceOperationalSetup); + 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 cd47eb0aaa842a..30f469932a800a 100644 --- a/src/controller/CommissioningDelegate.cpp +++ b/src/controller/CommissioningDelegate.cpp @@ -147,115 +147,115 @@ const char * MetricKeyForCommissioningStage(CommissioningStage stage) switch (stage) { case kError: - return "core_cm_stg_error"; + return "core_commissioning_stage_error"; case kSecurePairing: - return "core_cm_stg_secure_pairing"; + return "core_commissioning_stage_secure_pairing"; case kReadCommissioningInfo: - return "core_cm_stg_rd_comm_info"; + return "core_commissioning_stage_read_commissioning_info"; case kReadCommissioningInfo2: - return "core_cm_stg_rd_comm_info2"; + return "core_commissioning_stage_read_commissioning_info2"; case kArmFailsafe: - return "core_cm_stg_afs"; + return "core_commissioning_stage_arm_failsafe"; case kScanNetworks: - return "core_cm_stg_scn_nws"; + return "core_commissioning_stage_scan_networks"; case kConfigRegulatory: - return "core_cm_stg_cfg_reg"; + return "core_commissioning_stage_config_regulatory"; case kConfigureUTCTime: - return "core_cm_stg_cfg_utc"; + return "core_commissioning_stage_configure_utc_time"; case kConfigureTimeZone: - return "core_cm_stg_cfg_tmz"; + return "core_commissioning_stage_configure_timezone"; case kConfigureDSTOffset: - return "core_cm_stg_cfg_dst_off"; + return "core_commissioning_stage_configure_dst_offset"; case kConfigureDefaultNTP: - return "core_cm_stg_cfg_ntp"; + return "core_commissioning_stage_configure_default_ntp"; case kSendPAICertificateRequest: - return "core_cm_stg_csr_req"; + return "core_commissioning_stage_send_pai_certificate_request"; case kSendDACCertificateRequest: - return "core_cm_stg_dac_req"; + return "core_commissioning_stage_send_dac_certificate_request"; case kSendAttestationRequest: - return "core_cm_stg_att_req"; + return "core_commissioning_stage_send_attestation_request"; case kAttestationVerification: - return "core_cm_stg_att_ver"; + return "core_commissioning_stage_attestation_verification"; case kSendOpCertSigningRequest: - return "core_cm_stg_opcrt_csr"; + return "core_commissioning_stage_opcert_signing_request"; case kValidateCSR: - return "core_cm_stg_val_csr"; + return "core_commissioning_stage_validate_csr"; case kGenerateNOCChain: - return "core_cm_stg_gen_noc"; + return "core_commissioning_stage_generate_noc_chain"; case kSendTrustedRootCert: - return "core_cm_stg_trust_rca"; + return "core_commissioning_stage_send_trusted_root_cert"; case kSendNOC: - return "core_cm_stg_snd_noc"; + return "core_commissioning_stage_send_noc"; case kConfigureTrustedTimeSource: - return "core_cm_stg_cfg_tms"; + return "core_commissioning_stage_configure_trusted_time_source"; case kICDGetRegistrationInfo: - return "core_cm_stg_icd_reg_info"; + return "core_commissioning_stage_icd_get_registration_info"; case kICDRegistration: - return "core_cm_stg_icd_reg"; + return "core_commissioning_stage_icd_registration"; case kWiFiNetworkSetup: - return "core_cm_stg_wifi_nw_cred"; + return "core_commissioning_stage_wifi_network_setup"; case kThreadNetworkSetup: - return "core_cm_stg_thrd_nw_cred"; + return "core_commissioning_stage_thread_network_setup"; case kFailsafeBeforeWiFiEnable: - return "core_cm_stg_afs_bf_wifi"; + return "core_commissioning_stage_failsafe_before_wifi_enable"; case kFailsafeBeforeThreadEnable: - return "core_cm_stg_afs_bf_thrd"; + return "core_commissioning_stage_failsafe_before_thread_enable"; case kWiFiNetworkEnable: - return "core_cm_stg_wifi_enbl"; + return "core_commissioning_stage_wifi_network_enable"; case kThreadNetworkEnable: - return "core_cm_stg_thrd_enbl"; + return "core_commissioning_stage_thread_network_enable"; case kEvictPreviousCaseSessions: - return "core_cm_stg_evict_case"; + return "core_commissioning_stage_evict_previous_case_sessions"; case kFindOperationalForStayActive: - return "core_cm_stg_op_stay_active"; + return "core_commissioning_stage_find_operational_for_stay_active"; case kFindOperationalForCommissioningComplete: - return "core_cm_stg_op_cm_comp"; + return "core_commissioning_stage_find_operational_for_commissioning_complete"; case kICDSendStayActive: - return "core_cm_stg_icd_stay_act"; + return "core_commissioning_stage_icd_send_stay_active"; case kSendComplete: - return "core_cm_stg_snd_comp"; + return "core_commissioning_stage_send_complete"; case kCleanup: - return "core_cm_stg_cleanup"; + return "core_commissioning_stage_cleanup"; case kNeedsNetworkCreds: - return "core_cm_stg_need_nw_creds"; + return "core_commissioning_stage_need_network_creds"; default: - return "core_cm_stg_unknown"; + return "core_commissioning_stage_unknown"; } } #endif diff --git a/src/protocols/secure_channel/CASESession.cpp b/src/protocols/secure_channel/CASESession.cpp index aea8d9bd3e98e6..ccc2bc2188d176 100644 --- a/src/protocols/secure_channel/CASESession.cpp +++ b/src/protocols/secure_channel/CASESession.cpp @@ -47,7 +47,6 @@ #include #include #include -#include #include namespace { diff --git a/src/tracing/metric_keys.h b/src/tracing/metric_keys.h index f0b27e0d01b034..1064ee28954e54 100644 --- a/src/tracing/metric_keys.h +++ b/src/tracing/metric_keys.h @@ -35,21 +35,21 @@ constexpr MetricKey kMetricWiFiRSSI = "wifi_rssi"; constexpr MetricKey kMetricDeviceCommissionerPASESession = "core_dcm_pase_session"; // Overall commissioning into a fabric -constexpr MetricKey kMetricDeviceCommissionerCommission = "core_dcm_commission"; +constexpr MetricKey kMetricDeviceCommissionerCommission = "core_dcm_commission_device"; -constexpr MetricKey kMetricDeviceCommissionerCommissionStage = "core_ccm_commission_stage"; +constexpr MetricKey kMetricDeviceCommissionerCommissionStage = "core_dcm_commission_stage"; // Setup Code Pairer -constexpr MetricKey kMetricSetupCodePairerPairDevice = "core_scp_pair_dev"; +constexpr MetricKey kMetricSetupCodePairerPairDevice = "core_setup_code_pairer_pair_dev"; -// Operational Setup (Discovery + CASE) -constexpr MetricKey kMetricDeviceOperationalSetup = "core_dev_opr_setup"; +// Commissioning Operational Setup (Discovery + CASE) +constexpr MetricKey kMetricDeviceCommissioningOperationalSetup = "core_dcm_operational_setup"; // Operational Discovery -constexpr MetricKey kMetricDeviceOperationalDiscovery = "core_dev_opr_discovery"; +constexpr MetricKey kMetricDeviceOperationalDiscovery = "core_dev_operational_discovery"; // Operational Discovery Attempt Count -constexpr MetricKey kMetricDeviceOperationalDiscoveryAttemptCount = "core_dev_opdisc_attempt_ctr"; +constexpr MetricKey kMetricDeviceOperationalDiscoveryAttemptCount = "ore_dev_operational_discovery_attempt_ctr"; // CASE Session constexpr MetricKey kMetricDeviceCASESession = "core_dev_case_session"; From 67c629e67b45100a00f242b25755f7e171868941 Mon Sep 17 00:00:00 2001 From: Anush Nadathur Date: Mon, 13 May 2024 18:05:52 -0700 Subject: [PATCH 3/6] Fixed a typo --- src/tracing/metric_keys.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/tracing/metric_keys.h b/src/tracing/metric_keys.h index 1064ee28954e54..001e9c8036bd27 100644 --- a/src/tracing/metric_keys.h +++ b/src/tracing/metric_keys.h @@ -49,7 +49,7 @@ constexpr MetricKey kMetricDeviceCommissioningOperationalSetup = "core_dcm_opera constexpr MetricKey kMetricDeviceOperationalDiscovery = "core_dev_operational_discovery"; // Operational Discovery Attempt Count -constexpr MetricKey kMetricDeviceOperationalDiscoveryAttemptCount = "ore_dev_operational_discovery_attempt_ctr"; +constexpr MetricKey kMetricDeviceOperationalDiscoveryAttemptCount = "core_dev_operational_discovery_attempt_ctr"; // CASE Session constexpr MetricKey kMetricDeviceCASESession = "core_dev_case_session"; From d667a46b70239b2a6b6d951b52662630be0010b7 Mon Sep 17 00:00:00 2001 From: Anush Nadathur Date: Thu, 16 May 2024 16:00:47 -0700 Subject: [PATCH 4/6] Fixed Code Review Comment --- src/app/OperationalSessionSetup.cpp | 10 +++++++--- 1 file changed, 7 insertions(+), 3 deletions(-) diff --git a/src/app/OperationalSessionSetup.cpp b/src/app/OperationalSessionSetup.cpp index 9d429d46595936..c68809858723a3 100644 --- a/src/app/OperationalSessionSetup.cpp +++ b/src/app/OperationalSessionSetup.cpp @@ -307,9 +307,6 @@ CHIP_ERROR OperationalSessionSetup::EstablishConnection(const ReliableMessagePro mCASEClient = mClientPool->Allocate(); ReturnErrorCodeIf(mCASEClient == nullptr, CHIP_ERROR_NO_MEMORY); - // Session has been established. This is when discovery is also stopped - MATTER_LOG_METRIC_END(kMetricDeviceOperationalDiscovery, CHIP_NO_ERROR); - MATTER_LOG_METRIC_BEGIN(kMetricDeviceCASESession); CHIP_ERROR err = mCASEClient->EstablishSession(mInitParams, mPeerId, mDeviceAddress, config, this); if (err != CHIP_NO_ERROR) @@ -510,7 +507,11 @@ 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. } @@ -529,6 +530,9 @@ 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)) From 10cb21e51970abfb815a308cdb2722335a614925 Mon Sep 17 00:00:00 2001 From: Anush Nadathur Date: Thu, 16 May 2024 16:02:47 -0700 Subject: [PATCH 5/6] Update src/app/OperationalSessionSetup.cpp Co-authored-by: Boris Zbarsky --- src/app/OperationalSessionSetup.cpp | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/app/OperationalSessionSetup.cpp b/src/app/OperationalSessionSetup.cpp index c68809858723a3..00186961292820 100644 --- a/src/app/OperationalSessionSetup.cpp +++ b/src/app/OperationalSessionSetup.cpp @@ -620,8 +620,8 @@ CHIP_ERROR OperationalSessionSetup::LookupPeerAddress() return CHIP_NO_ERROR; } - // This call be called multiple times for each discovered address.The metric backend can handle this - // and always pick the earliest occurance as the start of the event. + // 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()); From f268b28cd5afcaf9601d6e95bdbae946b217776e Mon Sep 17 00:00:00 2001 From: Anush Nadathur Date: Fri, 17 May 2024 12:52:32 -0700 Subject: [PATCH 6/6] Resytler fixes --- src/app/OperationalSessionSetup.cpp | 1 - 1 file changed, 1 deletion(-) diff --git a/src/app/OperationalSessionSetup.cpp b/src/app/OperationalSessionSetup.cpp index 00186961292820..5733a423702226 100644 --- a/src/app/OperationalSessionSetup.cpp +++ b/src/app/OperationalSessionSetup.cpp @@ -507,7 +507,6 @@ 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);