[Metrics] Added additional metrics for CASE and Subscription (project-chip#33934)

* [Metrics] Added additional metrics for CASE and Subscription

- CASE session tracking
- Subscription Setup
- MRP Retries

* Fixed code review comment

* Restyler fixes

* Update src/darwin/Framework/CHIP/MTRDevice.mm

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

* Addressed code review comments

* Update src/darwin/Framework/CHIP/MTRMetricKeys.h

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

* Fixed build failure when tracing is off

* Resytle fixes

---------

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

Author: 2 people

src/app/ReadClient.cpp

@@ -33,6 +33,7 @@
 #include <messaging/ReliableMessageMgr.h>
 #include <messaging/ReliableMessageProtocolConfig.h>
 #include <platform/LockTracker.h>
+#include <tracing/metric_event.h>
 
 #include <app-common/zap-generated/cluster-objects.h>
 #include <app-common/zap-generated/ids/Attributes.h>
@@ -186,6 +187,11 @@ void ReadClient::Close(CHIP_ERROR aError, bool allowResubscription)
     }
     else
     {
+        if (IsAwaitingInitialReport() || IsAwaitingSubscribeResponse())
+        {
+            MATTER_LOG_METRIC_END(Tracing::kMetricDeviceSubscriptionSetup, aError);
+        }
+
         ClearActiveSubscriptionState();
         if (aError != CHIP_NO_ERROR)
         {
@@ -491,6 +497,7 @@ CHIP_ERROR ReadClient::OnMessageReceived(Messaging::ExchangeContext * apExchange
         ChipLogProgress(DataManagement, "SubscribeResponse is received");
         VerifyOrExit(apExchangeContext == mExchange.Get(), err = CHIP_ERROR_INCORRECT_STATE);
         err = ProcessSubscribeResponse(std::move(aPayload));
+        MATTER_LOG_METRIC_END(Tracing::kMetricDeviceSubscriptionSetup, err);
     }
     else if (aPayloadHeader.HasMessageType(Protocols::InteractionModel::MsgType::StatusResponse))
     {
@@ -684,6 +691,7 @@ void ReadClient::OnResponseTimeout(Messaging::ExchangeContext * apExchangeContex
 {
     ChipLogError(DataManagement, "Time out! failed to receive report data from Exchange: " ChipLogFormatExchange,
                  ChipLogValueExchange(apExchangeContext));
+
     Close(CHIP_ERROR_TIMEOUT);
 }
 
@@ -1096,11 +1104,18 @@ CHIP_ERROR ReadClient::SendSubscribeRequest(const ReadPrepareParams & aReadPrepa
     VerifyOrReturnError(aReadPrepareParams.mMinIntervalFloorSeconds <= aReadPrepareParams.mMaxIntervalCeilingSeconds,
                         CHIP_ERROR_INVALID_ARGUMENT);
 
-    return SendSubscribeRequestImpl(aReadPrepareParams);
+    auto err = SendSubscribeRequestImpl(aReadPrepareParams);
+    if (CHIP_NO_ERROR != err)
+    {
+        MATTER_LOG_METRIC_END(Tracing::kMetricDeviceSubscriptionSetup, err);
+    }
+    return err;
 }
 
 CHIP_ERROR ReadClient::SendSubscribeRequestImpl(const ReadPrepareParams & aReadPrepareParams)
 {
+    MATTER_LOG_METRIC_BEGIN(Tracing::kMetricDeviceSubscriptionSetup);
+
     VerifyOrReturnError(ClientState::Idle == mState, CHIP_ERROR_INCORRECT_STATE);
 
     if (&aReadPrepareParams != &mReadPrepareParams)

src/darwin/Framework/CHIP/MTRDevice.mm

@@ -160,6 +160,7 @@ - (void)_deviceInternalStateChanged:(MTRDevice *)device;
 using namespace chip;
 using namespace chip::app;
 using namespace chip::Protocols::InteractionModel;
+using namespace chip::Tracing::DarwinFramework;
 
 typedef void (^FirstReportHandler)(void);
 
@@ -1184,6 +1185,7 @@ - (void)_handleSubscriptionEstablished
     if (HadSubscriptionEstablishedOnce(_internalDeviceState)) {
         [self _changeInternalState:MTRInternalDeviceStateLaterSubscriptionEstablished];
     } else {
+        MATTER_LOG_METRIC_END(kMetricMTRDeviceInitialSubscriptionSetup, CHIP_NO_ERROR);
         [self _changeInternalState:MTRInternalDeviceStateInitialSubscriptionEstablished];
     }
 
@@ -2340,6 +2342,10 @@ - (void)_setupSubscriptionWithReason:(NSString *)reason
         });
     }
 
+    // This marks begin of initial subscription to the device (before CASE is established). The end is only marked after successfully setting
+    // up the subscription since it is always retried as long as the MTRDevice is kept running.
+    MATTER_LOG_METRIC_BEGIN(kMetricMTRDeviceInitialSubscriptionSetup);
+
     // Call directlyGetSessionForNode because the subscription setup already goes through the subscription pool queue
     [_deviceController
         directlyGetSessionForNode:_nodeID.unsignedLongLongValue

src/darwin/Framework/CHIP/MTRMetricKeys.h

@@ -16,6 +16,7 @@
 
 #include <lib/core/CHIPError.h>
 #include <tracing/metric_event.h>
+#include <tracing/metric_keys.h>
 
 namespace chip {
 namespace Tracing {
@@ -87,6 +88,9 @@ constexpr Tracing::MetricKey kMetricBLEDevicesRemoved = "dwnfw_ble_devices_remov
 // Unexpected C quality attribute update outside of priming
 constexpr Tracing::MetricKey kMetricUnexpectedCQualityUpdate = "dwnpm_bad_c_attr_update";
 
+// Setup from darwin MTRDevice for initial subscription to a device
+constexpr Tracing::MetricKey kMetricMTRDeviceInitialSubscriptionSetup = "dwnpm_dev_initial_subscription_setup";
+
 } // namespace DarwinFramework
 } // namespace Tracing
 } // namespace chip

src/messaging/ReliableMessageMgr.cpp

@@ -36,6 +36,7 @@
 #include <messaging/ReliableMessageContext.h>
 #include <messaging/ReliableMessageMgr.h>
 #include <platform/ConnectivityManager.h>
+#include <tracing/metric_event.h>
 
 #if CHIP_CONFIG_ENABLE_ICD_SERVER
 #include <app/icd/server/ICDConfigurationData.h> // nogncheck
@@ -170,6 +171,7 @@ void ReliableMessageMgr::ExecuteActions()
                         "Retransmitting MessageCounter:" ChipLogFormatMessageCounter " on exchange " ChipLogFormatExchange
                         " Send Cnt %d",
                         messageCounter, ChipLogValueExchange(&entry->ec.Get()), entry->sendCount);
+        MATTER_LOG_METRIC(Tracing::kMetricDeviceRMPRetryCount, entry->sendCount);
 
         CalculateNextRetransTime(*entry);
         SendFromRetransTable(entry);

src/protocols/secure_channel/CASESession.cpp

@@ -47,6 +47,7 @@
 #include <system/SystemClock.h>
 #include <system/TLVPacketBufferBackingStore.h>
 #include <tracing/macros.h>
+#include <tracing/metric_event.h>
 #include <transport/SessionManager.h>
 
 namespace {
@@ -101,6 +102,7 @@ using namespace Credentials;
 using namespace Messaging;
 using namespace Encoding;
 using namespace Protocols::SecureChannel;
+using namespace Tracing;
 
 constexpr uint8_t kKDFSR2Info[] = { 0x53, 0x69, 0x67, 0x6d, 0x61, 0x32 };
 constexpr uint8_t kKDFSR3Info[] = { 0x53, 0x69, 0x67, 0x6d, 0x61, 0x33 };
@@ -521,14 +523,15 @@ CHIP_ERROR CASESession::EstablishSession(SessionManager & sessionManager, Fabric
     CHIP_ERROR err = CHIP_NO_ERROR;
 
     // Return early on error here, as we have not initialized any state yet
-    ReturnErrorCodeIf(exchangeCtxt == nullptr, CHIP_ERROR_INVALID_ARGUMENT);
-    ReturnErrorCodeIf(fabricTable == nullptr, CHIP_ERROR_INVALID_ARGUMENT);
+    ReturnErrorCodeWithMetricIf(kMetricDeviceCASESession, exchangeCtxt == nullptr, CHIP_ERROR_INVALID_ARGUMENT);
+    ReturnErrorCodeWithMetricIf(kMetricDeviceCASESession, fabricTable == nullptr, CHIP_ERROR_INVALID_ARGUMENT);
 
     // Use FabricTable directly to avoid situation of dangling index from stale FabricInfo
     // until we factor-out any FabricInfo direct usage.
-    ReturnErrorCodeIf(peerScopedNodeId.GetFabricIndex() == kUndefinedFabricIndex, CHIP_ERROR_INVALID_ARGUMENT);
+    ReturnErrorCodeWithMetricIf(kMetricDeviceCASESession, peerScopedNodeId.GetFabricIndex() == kUndefinedFabricIndex,
+                                CHIP_ERROR_INVALID_ARGUMENT);
     const auto * fabricInfo = fabricTable->FindFabricWithIndex(peerScopedNodeId.GetFabricIndex());
-    ReturnErrorCodeIf(fabricInfo == nullptr, CHIP_ERROR_INVALID_ARGUMENT);
+    ReturnErrorCodeWithMetricIf(kMetricDeviceCASESession, fabricInfo == nullptr, CHIP_ERROR_INVALID_ARGUMENT);
 
     err = Init(sessionManager, policy, delegate, peerScopedNodeId);
 
@@ -542,9 +545,11 @@ CHIP_ERROR CASESession::EstablishSession(SessionManager & sessionManager, Fabric
 
     // From here onwards, let's go to exit on error, as some state might have already
     // been initialized
-    SuccessOrExit(err);
+    SuccessOrExitWithMetric(kMetricDeviceCASESession, err);
 
-    SuccessOrExit(err = fabricTable->AddFabricDelegate(this));
+    SuccessOrExitWithMetric(kMetricDeviceCASESession, err = fabricTable->AddFabricDelegate(this));
+
+    MATTER_LOG_METRIC_BEGIN(kMetricDeviceCASESession);
 
     // Set the PeerAddress in the secure session up front to indicate the
     // Transport Type of the session that is being set up.
@@ -571,13 +576,16 @@ CHIP_ERROR CASESession::EstablishSession(SessionManager & sessionManager, Fabric
     }
     else
     {
+        MATTER_LOG_METRIC_BEGIN(kMetricDeviceCASESessionSigma1);
         err = SendSigma1();
         SuccessOrExit(err);
     }
 
 exit:
     if (err != CHIP_NO_ERROR)
     {
+        MATTER_LOG_METRIC_END(kMetricDeviceCASESessionSigma1, err);
+        MATTER_LOG_METRIC_END(kMetricDeviceCASESession, err);
         Clear();
     }
     return err;
@@ -601,6 +609,7 @@ void CASESession::OnResponseTimeout(ExchangeContext * ec)
 
 void CASESession::AbortPendingEstablish(CHIP_ERROR err)
 {
+    MATTER_LOG_METRIC_END(kMetricDeviceCASESession, err);
     MATTER_TRACE_SCOPE("AbortPendingEstablish", "CASESession");
     // This needs to come before Clear() which will reset mState.
     SessionEstablishmentStage state = MapCASEStateToSessionEstablishmentStage(mState);
@@ -851,7 +860,17 @@ CHIP_ERROR CASESession::SendSigma1()
     ReturnErrorOnFailure(mExchangeCtxt.Value()->SendMessage(Protocols::SecureChannel::MsgType::CASE_Sigma1, std::move(msg_R1),
                                                             SendFlags(SendMessageFlags::kExpectResponse)));
 
-    mState = resuming ? State::kSentSigma1Resume : State::kSentSigma1;
+    if (resuming)
+    {
+        mState = State::kSentSigma1Resume;
+
+        // Flags that Resume is being attempted
+        MATTER_LOG_METRIC(kMetricDeviceCASESessionSigma1Resume);
+    }
+    else
+    {
+        mState = State::kSentSigma1;
+    }
 
     ChipLogProgress(SecureChannel, "Sent Sigma1 msg");
 
@@ -984,7 +1003,13 @@ CHIP_ERROR CASESession::HandleSigma1(System::PacketBufferHandle && msg)
         std::copy(resumptionId.begin(), resumptionId.end(), mResumeResumptionId.begin());
 
         // Send Sigma2Resume message to the initiator
-        SuccessOrExit(err = SendSigma2Resume());
+        MATTER_LOG_METRIC_BEGIN(kMetricDeviceCASESessionSigma2Resume);
+        err = SendSigma2Resume();
+        if (CHIP_NO_ERROR != err)
+        {
+            MATTER_LOG_METRIC_END(kMetricDeviceCASESessionSigma2Resume, err);
+        }
+        SuccessOrExit(err);
 
         mDelegate->OnSessionEstablishmentStarted();
 
@@ -1013,7 +1038,13 @@ CHIP_ERROR CASESession::HandleSigma1(System::PacketBufferHandle && msg)
     // mRemotePubKey.Length() == initiatorPubKey.size() == kP256_PublicKey_Length.
     memcpy(mRemotePubKey.Bytes(), initiatorPubKey.data(), mRemotePubKey.Length());
 
-    SuccessOrExit(err = SendSigma2());
+    MATTER_LOG_METRIC_BEGIN(kMetricDeviceCASESessionSigma2);
+    err = SendSigma2();
+    if (CHIP_NO_ERROR != err)
+    {
+        MATTER_LOG_METRIC_END(kMetricDeviceCASESessionSigma2, err);
+    }
+    SuccessOrExit(err);
 
     mDelegate->OnSessionEstablishmentStarted();
 
@@ -1236,6 +1267,7 @@ CHIP_ERROR CASESession::HandleSigma2Resume(System::PacketBufferHandle && msg)
 
     ChipLogDetail(SecureChannel, "Received Sigma2Resume msg");
     MATTER_TRACE_COUNTER("Sigma2Resume");
+    MATTER_LOG_METRIC_END(kMetricDeviceCASESessionSigma1, err);
 
     uint8_t sigma2ResumeMIC[CHIP_CRYPTO_AEAD_MIC_LENGTH_BYTES];
 
@@ -1278,6 +1310,7 @@ CHIP_ERROR CASESession::HandleSigma2Resume(System::PacketBufferHandle && msg)
             ChipLogError(SecureChannel, "Unable to save session resumption state: %" CHIP_ERROR_FORMAT, err2.Format());
     }
 
+    MATTER_LOG_METRIC(kMetricDeviceCASESessionSigmaFinished);
     SendStatusReport(mExchangeCtxt, kProtocolCodeSuccess);
 
     mState = State::kFinishedViaResume;
@@ -1294,10 +1327,17 @@ CHIP_ERROR CASESession::HandleSigma2Resume(System::PacketBufferHandle && msg)
 CHIP_ERROR CASESession::HandleSigma2_and_SendSigma3(System::PacketBufferHandle && msg)
 {
     MATTER_TRACE_SCOPE("HandleSigma2_and_SendSigma3", "CASESession");
-    ReturnErrorOnFailure(HandleSigma2(std::move(msg)));
-    ReturnErrorOnFailure(SendSigma3a());
+    CHIP_ERROR err = HandleSigma2(std::move(msg));
+    MATTER_LOG_METRIC_END(kMetricDeviceCASESessionSigma1, err);
+    ReturnErrorOnFailure(err);
 
-    return CHIP_NO_ERROR;
+    MATTER_LOG_METRIC_BEGIN(kMetricDeviceCASESessionSigma3);
+    err = SendSigma3a();
+    if (CHIP_NO_ERROR != err)
+    {
+        MATTER_LOG_METRIC_END(kMetricDeviceCASESessionSigma3, err);
+    }
+    return err;
 }
 
 CHIP_ERROR CASESession::HandleSigma2(System::PacketBufferHandle && msg)
@@ -1708,6 +1748,7 @@ CHIP_ERROR CASESession::HandleSigma3a(System::PacketBufferHandle && msg)
 
     ChipLogProgress(SecureChannel, "Received Sigma3 msg");
     MATTER_TRACE_COUNTER("Sigma3");
+    MATTER_LOG_METRIC_END(kMetricDeviceCASESessionSigma2, err);
 
     auto helper = WorkHelper<HandleSigma3Data>::Create(*this, &HandleSigma3b, &CASESession::HandleSigma3c);
     VerifyOrExit(helper, err = CHIP_ERROR_NO_MEMORY);
@@ -1888,6 +1929,7 @@ CHIP_ERROR CASESession::HandleSigma3c(HandleSigma3Data & data, CHIP_ERROR status
         }
     }
 
+    MATTER_LOG_METRIC(kMetricDeviceCASESessionSigmaFinished);
     SendStatusReport(mExchangeCtxt, kProtocolCodeSuccess);
 
     mState = State::kFinished;
@@ -2288,6 +2330,7 @@ CHIP_ERROR CASESession::OnMessageReceived(ExchangeContext * ec, const PayloadHea
 
         case MsgType::StatusReport:
             err = HandleStatusReport(std::move(msg), /* successExpected*/ false);
+            MATTER_LOG_METRIC_END(kMetricDeviceCASESessionSigma1, err);
             break;
 
         default:
@@ -2308,6 +2351,7 @@ CHIP_ERROR CASESession::OnMessageReceived(ExchangeContext * ec, const PayloadHea
 
         case MsgType::StatusReport:
             err = HandleStatusReport(std::move(msg), /* successExpected*/ false);
+            MATTER_LOG_METRIC_END(kMetricDeviceCASESessionSigma1, err);
             break;
 
         default:
@@ -2324,6 +2368,7 @@ CHIP_ERROR CASESession::OnMessageReceived(ExchangeContext * ec, const PayloadHea
 
         case MsgType::StatusReport:
             err = HandleStatusReport(std::move(msg), /* successExpected*/ false);
+            MATTER_LOG_METRIC_END(kMetricDeviceCASESessionSigma2, err);
             break;
 
         default:
@@ -2335,7 +2380,11 @@ CHIP_ERROR CASESession::OnMessageReceived(ExchangeContext * ec, const PayloadHea
     case State::kSentSigma2Resume:
         if (msgType == Protocols::SecureChannel::MsgType::StatusReport)
         {
-            err = HandleStatusReport(std::move(msg), /* successExpected*/ true);
+            // Need to capture before invoking status report since 'this' might be deallocated on successful completion of sigma3
+            MetricKey key = (mState == State::kSentSigma3) ? kMetricDeviceCASESessionSigma3 : kMetricDeviceCASESessionSigma2Resume;
+            err           = HandleStatusReport(std::move(msg), /* successExpected*/ true);
+            MATTER_LOG_METRIC_END(key, err);
+            IgnoreUnusedVariable(key);
         }
         break;
     default:

src/tracing/metric_keys.h

@@ -54,5 +54,29 @@ constexpr MetricKey kMetricDeviceOperationalDiscoveryAttemptCount = "core_dev_op
 // CASE Session
 constexpr MetricKey kMetricDeviceCASESession = "core_dev_case_session";
 
+// CASE Session Sigma1
+constexpr MetricKey kMetricDeviceCASESessionSigma1 = "core_dev_case_session_sigma1";
+
+// CASE Session Sigma1Resume
+constexpr MetricKey kMetricDeviceCASESessionSigma1Resume = "core_dev_case_session_sigma1_resume";
+
+// CASE Session Sigma2
+constexpr MetricKey kMetricDeviceCASESessionSigma2 = "core_dev_case_session_sigma2";
+
+// CASE Session Sigma3
+constexpr MetricKey kMetricDeviceCASESessionSigma3 = "core_dev_case_session_sigma3";
+
+// CASE Session Sigma2 Resume
+constexpr MetricKey kMetricDeviceCASESessionSigma2Resume = "core_dev_case_session_sigma2_resume";
+
+// CASE Session SigmaFinished
+constexpr MetricKey kMetricDeviceCASESessionSigmaFinished = "core_dev_case_session_sigma_finished";
+
+// MRP Retry Counter
+constexpr MetricKey kMetricDeviceRMPRetryCount = "core_dev_rmp_retry_count";
+
+// Subscription setup
+constexpr MetricKey kMetricDeviceSubscriptionSetup = "core_dev_subscription_setup";
+
 } // namespace Tracing
 } // namespace chip