Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Metrics] Metrics in core commissioning phase #33247

Merged
merged 6 commits into from
May 17, 2024
Merged

[Metrics] Metrics in core commissioning phase #33247

Show file tree
Hide file tree
Changes from 5 commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
ae4460a
[Metrics] Metrics in core commissioning phase
anush-apple Apr 3, 2024
062f165
Fixing code review comments
anush-apple May 11, 2024
67c629e
Fixed a typo
anush-apple May 14, 2024
d667a46
Fixed Code Review Comment
anush-apple May 16, 2024
10cb21e
Update src/app/OperationalSessionSetup.cpp
anush-apple May 16, 2024
f268b28
Resytler fixes
anush-apple May 17, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
23 changes: 23 additions & 0 deletions src/app/OperationalSessionSetup.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 {

Expand Down Expand Up @@ -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;
}
Expand Down Expand Up @@ -503,6 +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.
}
Expand All @@ -521,6 +530,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
Expand Down Expand Up @@ -591,6 +605,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
Expand All @@ -605,6 +620,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);

Expand Down Expand Up @@ -676,6 +695,8 @@ void OperationalSessionSetup::OnNodeAddressResolutionFailed(const PeerId & peerI
--mAttemptsDone;
}

MATTER_LOG_METRIC(kMetricDeviceOperationalDiscoveryAttemptCount, mAttemptsDone);

CHIP_ERROR err = LookupPeerAddress();
if (err == CHIP_NO_ERROR)
{
Expand All @@ -690,6 +711,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.
Expand Down
40 changes: 34 additions & 6 deletions src/controller/CHIPDeviceController.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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>
Expand All @@ -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 {
Expand Down Expand Up @@ -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,
Expand All @@ -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;
Expand Down Expand Up @@ -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())
Expand Down Expand Up @@ -818,6 +827,7 @@ CHIP_ERROR DeviceCommissioner::EstablishPASEConnection(NodeId remoteDeviceId, Re
{
ReleaseCommissioneeDevice(device);
}
MATTER_LOG_METRIC_END(kMetricDeviceCommissionerPASESession, err);
}

return err;
Expand Down Expand Up @@ -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)
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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);
Expand All @@ -1094,6 +1110,7 @@ void DeviceCommissioner::OnSessionEstablished(const SessionHandle & session)
if (mRunCommissioningAfterConnection)
{
mRunCommissioningAfterConnection = false;
MATTER_LOG_METRIC_BEGIN(kMetricDeviceCommissionerCommission);
mDefaultCommissioner->StartCommissioning(this, device);
}
}
Expand Down Expand Up @@ -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;
Expand All @@ -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)
Expand All @@ -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();
Expand Down Expand Up @@ -1978,6 +1999,7 @@ void DeviceCommissioner::OnDeviceConnectedFn(void * context, Messaging::Exchange
const SessionHandle & sessionHandle)
{
// CASE session established.
MATTER_LOG_METRIC_END(kMetricDeviceCommissioningOperationalSetup, CHIP_NO_ERROR);
DeviceCommissioner * commissioner = static_cast<DeviceCommissioner *>(context);
VerifyOrDie(commissioner->mCommissioningStage == CommissioningStage::kFindOperationalForStayActive ||
commissioner->mCommissioningStage == CommissioningStage::kFindOperationalForCommissioningComplete);
Expand All @@ -1992,6 +2014,7 @@ void DeviceCommissioner::OnDeviceConnectedFn(void * context, Messaging::Exchange
void DeviceCommissioner::OnDeviceConnectionFailureFn(void * context, const ScopedNodeId & peerId, CHIP_ERROR error)
{
// CASE session establishment failed.
MATTER_LOG_METRIC_END(kMetricDeviceCommissioningOperationalSetup, error);
DeviceCommissioner * commissioner = static_cast<DeviceCommissioner *>(context);
VerifyOrDie(commissioner->mCommissioningStage == CommissioningStage::kFindOperationalForStayActive ||
commissioner->mCommissioningStage == CommissioningStage::kFindOperationalForCommissioningComplete);
Expand Down Expand Up @@ -2748,7 +2771,11 @@ void DeviceCommissioner::SendCommissioningReadRequest(DeviceProxy * proxy, Optio
void DeviceCommissioner::PerformCommissioningStep(DeviceProxy * proxy, CommissioningStage step, CommissioningParameters & params,
CommissioningDelegate * delegate, EndpointId endpoint,
Optional<System::Clock::Timeout> timeout)

{
MATTER_LOG_METRIC(kMetricDeviceCommissionerCommissionStage, step);
MATTER_LOG_METRIC_BEGIN(MetricKeyForCommissioningStage(step));

if (params.GetCompletionStatus().err == CHIP_NO_ERROR)
{
ChipLogProgress(Controller, "Performing next commissioning step '%s'", StageToString(step));
Expand Down Expand Up @@ -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
Expand Down
119 changes: 119 additions & 0 deletions src/controller/CommissioningDelegate.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Loading
Loading