Add more prints to AutoCommissioner/CASESessionManager (#14736)

* Add more prints to AutoCommissioner/CASESessionManager This not only provides more insights into the mechanics of the commissioning state machinery but the state transitions with the controller-side CASE session machinery. This is needed to debug some hairy race conditions when commissioning onto multiple fabrics. * Update src/app/OperationalDeviceProxy.cpp Co-authored-by: Michael Sandstedt <michael.sandstedt@gmail.com> * Review feedback + some more prints. * Minor fixups. * Missed a file Co-authored-by: Justin Wood <woody@apple.com> Co-authored-by: Michael Sandstedt <michael.sandstedt@gmail.com>
project-chip · Apr 13, 2022 · e6068ed · e6068ed
1 parent ebcc44e
commit e6068ed
Show file tree

Hide file tree

Showing 14 changed files with 168 additions and 17 deletions.
diff --git a/src/app/CASESessionManager.cpp b/src/app/CASESessionManager.cpp
@@ -38,9 +38,15 @@ CHIP_ERROR CASESessionManager::FindOrEstablishSession(PeerId peerId, Callback::C
         false;
 #endif
 
+    ChipLogDetail(CASESessionManager,
+                  "FindOrEstablishSession: PeerId = " ChipLogFormatX64 ":" ChipLogFormatX64 ", NodeIdWasResolved = %d",
+                  ChipLogValueX64(peerId.GetCompressedFabricId()), ChipLogValueX64(peerId.GetNodeId()), nodeIDWasResolved);
+
     OperationalDeviceProxy * session = FindExistingSession(peerId);
     if (session == nullptr)
     {
+        ChipLogDetail(CASESessionManager, "FindOrEstablishSession: No existing session found");
+
         // TODO - Implement LRU to evict least recently used session to handle mActiveSessions pool exhaustion
         if (nodeIDWasResolved)
         {

diff --git a/src/app/OperationalDeviceProxy.cpp b/src/app/OperationalDeviceProxy.cpp
@@ -46,6 +46,17 @@ using chip::AddressResolve::ResolveResult;
 
 namespace chip {
 
+void OperationalDeviceProxy::MoveToState(State aTargetState)
+{
+    if (mState != aTargetState)
+    {
+        ChipLogDetail(Controller, "OperationalDeviceProxy[" ChipLogFormatX64 ":" ChipLogFormatX64 "]: State change %d --> %d",
+                      ChipLogValueX64(mPeerId.GetCompressedFabricId()), ChipLogValueX64(mPeerId.GetNodeId()), to_underlying(mState),
+                      to_underlying(aTargetState));
+        mState = aTargetState;
+    }
+}
+
 CHIP_ERROR OperationalDeviceProxy::Connect(Callback::Callback<OnDeviceConnected> * onConnection,
                                            Callback::Callback<OnDeviceConnectionFailure> * onFailure)
 {
@@ -118,8 +129,8 @@ CHIP_ERROR OperationalDeviceProxy::UpdateDeviceData(const Transport::PeerAddress
 
     if (mState == State::NeedsAddress)
     {
-        mState = State::Initialized;
-        err    = EstablishConnection();
+        MoveToState(State::Initialized);
+        err = EstablishConnection();
         if (err != CHIP_NO_ERROR)
         {
             OnSessionEstablishmentError(err);
@@ -163,7 +174,7 @@ CHIP_ERROR OperationalDeviceProxy::EstablishConnection()
         mCASEClient->EstablishSession(mPeerId, mDeviceAddress, mMRPConfig, HandleCASEConnected, HandleCASEConnectionFailure, this);
     ReturnErrorOnFailure(err);
 
-    mState = State::Connecting;
+    MoveToState(State::Connecting);
 
     return CHIP_NO_ERROR;
 }
@@ -222,7 +233,7 @@ void OperationalDeviceProxy::HandleCASEConnectionFailure(void * context, CASECli
                    ChipLogError(Controller, "HandleCASEConnectionFailure was called while the device was not initialized"));
     VerifyOrReturn(client == device->mCASEClient, ChipLogError(Controller, "HandleCASEConnectionFailure for unknown CASEClient"));
 
-    device->mState = State::Initialized;
+    device->MoveToState(State::Initialized);
 
     device->CloseCASESession();
     device->DequeueConnectionSuccessCallbacks(/* executeCallback */ false);
@@ -247,7 +258,7 @@ void OperationalDeviceProxy::HandleCASEConnected(void * context, CASEClient * cl
     }
     else
     {
-        device->mState = State::SecureConnected;
+        device->MoveToState(State::SecureConnected);
 
         device->CloseCASESession();
         device->DequeueConnectionFailureCallbacks(CHIP_NO_ERROR, /* executeCallback */ false);
@@ -264,7 +275,7 @@ CHIP_ERROR OperationalDeviceProxy::Disconnect()
     {
         mInitParams.sessionManager->ExpirePairing(mSecureSession.Get());
     }
-    mState = State::Initialized;
+    MoveToState(State::Initialized);
     if (mCASEClient)
     {
         mInitParams.clientPool->Release(mCASEClient);
@@ -276,7 +287,7 @@ CHIP_ERROR OperationalDeviceProxy::Disconnect()
 void OperationalDeviceProxy::SetConnectedSession(const SessionHandle & handle)
 {
     mSecureSession.Grab(handle);
-    mState = State::SecureConnected;
+    MoveToState(State::SecureConnected);
 }
 
 void OperationalDeviceProxy::Clear()
@@ -287,7 +298,7 @@ void OperationalDeviceProxy::Clear()
         mCASEClient = nullptr;
     }
 
-    mState      = State::Uninitialized;
+    MoveToState(State::Uninitialized);
     mInitParams = DeviceProxyInitParams();
 }
 
@@ -302,7 +313,7 @@ void OperationalDeviceProxy::CloseCASESession()
 
 void OperationalDeviceProxy::OnSessionReleased()
 {
-    mState = State::Initialized;
+    MoveToState(State::Initialized);
 }
 
 CHIP_ERROR OperationalDeviceProxy::ShutdownSubscriptions()

diff --git a/src/app/OperationalDeviceProxy.h b/src/app/OperationalDeviceProxy.h
@@ -246,6 +246,8 @@ class DLL_EXPORT OperationalDeviceProxy : public DeviceProxy,
 
     Transport::PeerAddress mDeviceAddress = Transport::PeerAddress::UDP(Inet::IPAddress::Any);
 
+    void MoveToState(State aTargetState);
+
     State mState = State::Uninitialized;
 
     SessionHolderWithDelegate mSecureSession;

diff --git a/src/controller/AutoCommissioner.cpp b/src/controller/AutoCommissioner.cpp
@@ -102,6 +102,14 @@ CHIP_ERROR AutoCommissioner::SetCommissioningParameters(const CommissioningParam
 }
 
 CommissioningStage AutoCommissioner::GetNextCommissioningStage(CommissioningStage currentStage, CHIP_ERROR & lastErr)
+{
+    auto nextStage = GetNextCommissioningStageInternal(currentStage, lastErr);
+    ChipLogProgress(Controller, "Going from commissioning step '%s' with lastErr = '%s' --> '%s'", StageToString(currentStage),
+                    lastErr.AsString(), StageToString(nextStage));
+    return nextStage;
+}
+
+CommissioningStage AutoCommissioner::GetNextCommissioningStageInternal(CommissioningStage currentStage, CHIP_ERROR & lastErr)
 {
     if (lastErr != CHIP_NO_ERROR)
     {
@@ -320,6 +328,9 @@ CHIP_ERROR AutoCommissioner::CommissioningStepFinished(CHIP_ERROR err, Commissio
     }
     else
     {
+        ChipLogProgress(Controller, "Finished commissioning step '%s' with error '%s'", StageToString(report.stageCompleted),
+                        err.AsString());
+
         switch (report.stageCompleted)
         {
         case CommissioningStage::kReadCommissioningInfo:

diff --git a/src/controller/AutoCommissioner.h b/src/controller/AutoCommissioner.h
@@ -39,6 +39,7 @@ class AutoCommissioner : public CommissioningDelegate
 
 private:
     CommissioningStage GetNextCommissioningStage(CommissioningStage currentStage, CHIP_ERROR & lastErr);
+    CommissioningStage GetNextCommissioningStageInternal(CommissioningStage currentStage, CHIP_ERROR & lastErr);
     void ReleaseDAC();
     void ReleasePAI();
 

diff --git a/src/controller/BUILD.gn b/src/controller/BUILD.gn
@@ -46,6 +46,7 @@ static_library("controller") {
       "CommissioneeDeviceProxy.h",
       "CommissionerDiscoveryController.cpp",
       "CommissionerDiscoveryController.h",
+      "CommissioningDelegate.cpp",
       "DeviceDiscoveryDelegate.h",
       "EmptyDataModelHandler.cpp",
       "ExampleOperationalCredentialsIssuer.cpp",

diff --git a/src/controller/CHIPDeviceController.cpp b/src/controller/CHIPDeviceController.cpp
@@ -1753,6 +1753,9 @@ void DeviceCommissioner::PerformCommissioningStep(DeviceProxy * proxy, Commissio
                                                   CommissioningDelegate * delegate, EndpointId endpoint,
                                                   Optional<System::Clock::Timeout> timeout)
 {
+    ChipLogProgress(Controller, "Performing next commissioning step '%s' with completion status = '%s'", StageToString(step),
+                    params.GetCompletionStatus().AsString());
+
     // For now, we ignore errors coming in from the device since not all commissioning clusters are implemented on the device
     // side.
     mCommissioningStage    = step;
@@ -1997,7 +2000,6 @@ void DeviceCommissioner::PerformCommissioningStep(DeviceProxy * proxy, Commissio
             CommissioningStageComplete(CHIP_ERROR_INVALID_ARGUMENT);
             return;
         }
-        ChipLogProgress(Controller, "Sending operational certificate chain to the device");
         SendOperationalCertificate(proxy, params.GetNoc().Value(), params.GetIcac().Value(), params.GetIpk().Value(),
                                    params.GetAdminSubject().Value());
         break;
@@ -2009,7 +2011,6 @@ void DeviceCommissioner::PerformCommissioningStep(DeviceProxy * proxy, Commissio
             return;
         }
 
-        ChipLogProgress(Controller, "Adding wifi network");
         NetworkCommissioning::Commands::AddOrUpdateWiFiNetwork::Type request;
         request.ssid        = params.GetWiFiCredentials().Value().ssid;
         request.credentials = params.GetWiFiCredentials().Value().credentials;
@@ -2024,7 +2025,6 @@ void DeviceCommissioner::PerformCommissioningStep(DeviceProxy * proxy, Commissio
             CommissioningStageComplete(CHIP_ERROR_INVALID_ARGUMENT);
             return;
         }
-        ChipLogProgress(Controller, "Adding thread network");
         NetworkCommissioning::Commands::AddOrUpdateThreadNetwork::Type request;
         request.operationalDataset = params.GetThreadOperationalDataset().Value();
         request.breadcrumb         = breadcrumb;
@@ -2038,7 +2038,6 @@ void DeviceCommissioner::PerformCommissioningStep(DeviceProxy * proxy, Commissio
             CommissioningStageComplete(CHIP_ERROR_INVALID_ARGUMENT);
             return;
         }
-        ChipLogProgress(Controller, "Enabling wifi network");
         NetworkCommissioning::Commands::ConnectNetwork::Type request;
         request.networkID  = params.GetWiFiCredentials().Value().ssid;
         request.breadcrumb = breadcrumb;
@@ -2056,7 +2055,6 @@ void DeviceCommissioner::PerformCommissioningStep(DeviceProxy * proxy, Commissio
             CommissioningStageComplete(CHIP_ERROR_INVALID_ARGUMENT);
             return;
         }
-        ChipLogProgress(Controller, "Enabling thread network");
         NetworkCommissioning::Commands::ConnectNetwork::Type request;
         request.networkID  = extendedPanId;
         request.breadcrumb = breadcrumb;
@@ -2074,14 +2072,12 @@ void DeviceCommissioner::PerformCommissioningStep(DeviceProxy * proxy, Commissio
     }
     break;
     case CommissioningStage::kSendComplete: {
-        ChipLogProgress(Controller, "Calling commissioning complete");
         GeneralCommissioning::Commands::CommissioningComplete::Type request;
         SendCommand<NetworkCommissioningCluster>(proxy, request, OnCommissioningCompleteResponse, OnBasicFailure, endpoint,
                                                  timeout);
     }
     break;
     case CommissioningStage::kCleanup:
-        ChipLogProgress(Controller, "Rendezvous cleanup");
         if (mPairingDelegate != nullptr)
         {
             mPairingDelegate->OnCommissioningComplete(proxy->GetDeviceId(), params.GetCompletionStatus());

diff --git a/src/controller/CommissioningDelegate.cpp b/src/controller/CommissioningDelegate.cpp
@@ -0,0 +1,111 @@
+/*
+ *
+ *    Copyright (c) 2021 Project CHIP Authors
+ *    All rights reserved.
+ *
+ *    Licensed under the Apache License, Version 2.0 (the "License");
+ *    you may not use this file except in compliance with the License.
+ *    You may obtain a copy of the License at
+ *
+ *        http://www.apache.org/licenses/LICENSE-2.0
+ *
+ *    Unless required by applicable law or agreed to in writing, software
+ *    distributed under the License is distributed on an "AS IS" BASIS,
+ *    WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ *    See the License for the specific language governing permissions and
+ *    limitations under the License.
+ */
+
+#include <controller/CommissioningDelegate.h>
+
+namespace chip {
+namespace Controller {
+
+const char * StageToString(CommissioningStage stage)
+{
+    switch (stage)
+    {
+    case kError:
+        return "Error";
+        break;
+
+    case kSecurePairing:
+        return "SecurePairing";
+        break;
+
+    case kArmFailsafe:
+        return "ArmFailSafe";
+        break;
+
+    case kConfigRegulatory:
+        return "ConfigRegulatory";
+        break;
+
+    case kSendPAICertificateRequest:
+        return "SendPAICertificateRequest";
+        break;
+
+    case kSendDACCertificateRequest:
+        return "SendDACCertificateRequest";
+        break;
+
+    case kSendAttestationRequest:
+        return "SendAttestationRequest";
+        break;
+
+    case kAttestationVerification:
+        return "AttestationVerification";
+        break;
+
+    case kSendOpCertSigningRequest:
+        return "SendOpCertSigningRequest";
+        break;
+
+    case kGenerateNOCChain:
+        return "GenerateNOCChain";
+        break;
+
+    case kSendTrustedRootCert:
+        return "SendTrustedRootCert";
+        break;
+
+    case kSendNOC:
+        return "SendNOC";
+        break;
+
+    case kWiFiNetworkSetup:
+        return "WiFiNetworkSetup";
+        break;
+
+    case kThreadNetworkSetup:
+        return "ThreadNetworkSetup";
+        break;
+
+    case kWiFiNetworkEnable:
+        return "WiFiNetworkEnable";
+        break;
+
+    case kThreadNetworkEnable:
+        return "ThreadNetworkEnable";
+        break;
+
+    case kFindOperational:
+        return "FindOperational";
+        break;
+
+    case kSendComplete:
+        return "SendComplete";
+        break;
+
+    case kCleanup:
+        return "Cleanup";
+        break;
+
+    default:
+        return "???";
+        break;
+    }
+}
+
+} // namespace Controller
+} // namespace chip
diff --git a/src/controller/CommissioningDelegate.h b/src/controller/CommissioningDelegate.h
@@ -51,6 +51,8 @@ enum CommissioningStage : uint8_t
     kCleanup,
 };
 
+const char * StageToString(CommissioningStage stage);
+
 struct WiFiCredentials
 {
     ByteSpan ssid;

diff --git a/src/lib/dnssd/Discovery_ImplPlatform.cpp b/src/lib/dnssd/Discovery_ImplPlatform.cpp
@@ -626,6 +626,10 @@ Resolver & chip::Dnssd::Resolver::Instance()
 CHIP_ERROR ResolverProxy::ResolveNodeId(const PeerId & peerId, Inet::IPAddressType type)
 {
     VerifyOrReturnError(mDelegate != nullptr, CHIP_ERROR_INCORRECT_STATE);
+
+    ChipLogProgress(Discovery, "Resolving " ChipLogFormatX64 ":" ChipLogFormatX64 " ...",
+                    ChipLogValueX64(peerId.GetCompressedFabricId()), ChipLogValueX64(peerId.GetNodeId()));
+
     mDelegate->Retain();
 
     DnssdService service;

diff --git a/src/lib/dnssd/Resolver.h b/src/lib/dnssd/Resolver.h
@@ -47,7 +47,8 @@ struct ResolvedNodeData
 
         // Would be nice to log the interface id, but sorting out how to do so
         // across our differnet InterfaceId implementations is a pain.
-        ChipLogProgress(Discovery, "Node ID resolved for 0x" ChipLogFormatX64, ChipLogValueX64(mPeerId.GetNodeId()));
+        ChipLogProgress(Discovery, "Node ID resolved for " ChipLogFormatX64 ":" ChipLogFormatX64,
+                        ChipLogValueX64(mPeerId.GetCompressedFabricId()), ChipLogValueX64(mPeerId.GetNodeId()));
         for (unsigned i = 0; i < mNumIPs; ++i)
         {
             mAddress[i].ToString(addrBuffer);

diff --git a/src/lib/dnssd/Resolver_ImplMinimalMdns.cpp b/src/lib/dnssd/Resolver_ImplMinimalMdns.cpp
@@ -683,6 +683,9 @@ Resolver & chip::Dnssd::Resolver::Instance()
 CHIP_ERROR ResolverProxy::ResolveNodeId(const PeerId & peerId, Inet::IPAddressType type)
 {
     VerifyOrReturnError(mDelegate != nullptr, CHIP_ERROR_INCORRECT_STATE);
+
+    ChipLogProgress(Discovery, "Resolving " ChipLogFormatX64 ":" ChipLogFormatX64 " ...",
+                    ChipLogValueX64(peerId.GetCompressedFabricId()), ChipLogValueX64(peerId.GetNodeId()));
     chip::Dnssd::Resolver::Instance().SetOperationalDelegate(mDelegate);
     return chip::Dnssd::Resolver::Instance().ResolveNodeId(peerId, type);
 }

diff --git a/src/lib/support/logging/CHIPLogging.cpp b/src/lib/support/logging/CHIPLogging.cpp
@@ -116,6 +116,7 @@ const char ModuleNames[] = "-\0\0" // None
                            "TST"   // Test
                            "ODP"   // OperationalDeviceProxy
                            "ATM"   // Automation
+                           "CSM"   // CASESessionManager
     ;
 
 #define ModuleNamesCount ((sizeof(ModuleNames) - 1) / chip::Logging::kMaxModuleNameLen)

diff --git a/src/lib/support/logging/Constants.h b/src/lib/support/logging/Constants.h
@@ -58,6 +58,7 @@ enum LogModule
     kLogModule_Test,
     kLogModule_OperationalDeviceProxy,
     kLogModule_Automation,
+    kLogModule_CASESessionManager,
 
     kLogModule_Max
 };