[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>
diff --git a/src/app/OperationalSessionSetup.cpp b/src/app/OperationalSessionSetup.cpp
index 9d91b7b..5733a42 100644
--- a/src/app/OperationalSessionSetup.cpp
+++ b/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 @@
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 @@
#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 @@
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 @@
{
--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 @@
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 @@
--mAttemptsDone;
}
+ MATTER_LOG_METRIC(kMetricDeviceOperationalDiscoveryAttemptCount, mAttemptsDone);
+
CHIP_ERROR err = LookupPeerAddress();
if (err == CHIP_NO_ERROR)
{
@@ -690,6 +710,8 @@
}
#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 910c0b2..1381ed3 100644
--- a/src/controller/CHIPDeviceController.cpp
+++ b/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::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, 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, 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 @@
// 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 @@
{
ReleaseCommissioneeDevice(device);
}
+ MATTER_LOG_METRIC_END(kMetricDeviceCommissionerPASESession, err);
}
return err;
@@ -869,8 +879,10 @@
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 @@
mDefaultCommissioner->SetOperationalCredentialsDelegate(mOperationalCredentialsDelegate);
if (device->IsSecureConnected())
{
+ MATTER_LOG_METRIC_BEGIN(kMetricDeviceCommissionerCommission);
mDefaultCommissioner->StartCommissioning(this, device);
}
else
@@ -1058,6 +1071,8 @@
void DeviceCommissioner::OnSessionEstablishmentError(CHIP_ERROR err)
{
+ MATTER_LOG_METRIC_END(kMetricDeviceCommissionerPASESession, err);
+
if (mPairingDelegate != nullptr)
{
mPairingDelegate->OnStatusUpdate(DevicePairingDelegate::SecurePairingFailed);
@@ -1086,6 +1101,7 @@
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 @@
if (mRunCommissioningAfterConnection)
{
mRunCommissioningAfterConnection = false;
+ MATTER_LOG_METRIC_BEGIN(kMetricDeviceCommissionerCommission);
mDefaultCommissioner->StartCommissioning(this, device);
}
}
@@ -1916,6 +1933,8 @@
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 @@
{
return;
}
+
mPairingDelegate->OnCommissioningComplete(nodeId, completionStatus.err);
PeerId peerId(GetCompressedFabricId(), nodeId);
if (completionStatus.err == CHIP_NO_ERROR)
@@ -1943,6 +1963,7 @@
{
// 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 @@
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::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::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 @@
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 b3e3b6c..30f4699 100644
--- a/src/controller/CommissioningDelegate.cpp
+++ b/src/controller/CommissioningDelegate.cpp
@@ -141,5 +141,124 @@
}
}
+#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 e79ad1d..57d6a0c 100644
--- a/src/controller/CommissioningDelegate.h
+++ b/src/controller/CommissioningDelegate.h
@@ -24,6 +24,7 @@
#include <credentials/attestation_verifier/DeviceAttestationVerifier.h>
#include <crypto/CHIPCryptoPAL.h>
#include <lib/support/Variant.h>
+#include <matter/tracing/build_config.h>
#include <system/SystemClock.h>
namespace chip {
@@ -89,6 +90,10 @@
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 4eb107a..8ebf78a 100644
--- a/src/controller/SetUpCodePairer.cpp
+++ b/src/controller/SetUpCodePairer.cpp
@@ -30,9 +30,12 @@
#include <lib/dnssd/Resolver.h>
#include <lib/support/CodeUtils.h>
#include <system/SystemClock.h>
+#include <tracing/metric_event.h>
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 SetUpCodePairer::PairDevice(NodeId remoteId, const char * setUpCode, SetupCodePairerBehaviour commission,
DiscoveryType discoveryType, Optional<Dnssd::CommonResolutionData> 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 @@
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 @@
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 @@
return;
}
+ MATTER_LOG_METRIC_END(kMetricSetupCodePairerPairDevice, error);
if (pairingDelegate != nullptr)
{
pairingDelegate->OnPairingComplete(error);
@@ -608,6 +620,7 @@
{
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 9c4b0a4..16b4d7f 100644
--- a/src/darwin/Framework/CHIP/MTRDeviceController.mm
+++ b/src/darwin/Framework/CHIP/MTRDeviceController.mm
@@ -627,12 +627,6 @@
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 @@
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 @@
auto pinCode = static_cast<uint32_t>(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 @@
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 @@
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 @@
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 @@
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 2f80af9..001e9c8 100644
--- a/src/tracing/metric_keys.h
+++ b/src/tracing/metric_keys.h
@@ -31,5 +31,28 @@
*/
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 26dde8c..3d00e7d 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 916a002..17e4cd6 100644
--- a/src/tracing/tests/TestMetricEvents.cpp
+++ b/src/tracing/tests/TestMetricEvents.cpp
@@ -597,17 +597,17 @@
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<MetricEvent> 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());
