Add more prints to AutoCommissioner/CASESessionManager

src/app/CASESessionManager.cpp

@@ -28,9 +28,15 @@ CHIP_ERROR CASESessionManager::FindOrEstablishSession(PeerId peerId, Callback::C
 
     bool nodeIDWasResolved = (mConfig.dnsCache != nullptr && mConfig.dnsCache->Lookup(peerId, resolutionData) == CHIP_NO_ERROR);
 
+    ChipLogDetail(CASESessionManager,
+                  "FindOrEstablishSession: PeerId = CF" ChipLogFormatX64 ":N" 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)
         {

src/app/OperationalDeviceProxy.cpp

@@ -42,6 +42,18 @@ using namespace chip::Callback;
 
 namespace chip {
 
+void OperationalDeviceProxy::MoveToState(State aTargetState)
+{
+    if (mState != aTargetState)
+    {
+        ChipLogDetail(Controller,
+                      "OperationalDeviceProxy[CF" ChipLogFormatX64 ":" ChipLogFormatX64 "]: Moving from state %d --> %d",
+                      ChipLogValueX64(mPeerId.GetCompressedFabricId()), ChipLogValueX64(mPeerId.GetNodeId()), (uint32_t) mState,
+                      (uint32_t) aTargetState);
+        mState = aTargetState;
+    }
+}
+
 CHIP_ERROR OperationalDeviceProxy::Connect(Callback::Callback<OnDeviceConnected> * onConnection,
                                            Callback::Callback<OnDeviceConnectionFailure> * onFailure,
                                            Dnssd::ResolverProxy * resolver)
@@ -109,8 +121,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);
@@ -154,7 +166,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;
 }
@@ -213,7 +225,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->DequeueConnectionSuccessCallbacks(/* executeCallback */ false);
     device->DequeueConnectionFailureCallbacks(error, /* executeCallback */ true);
@@ -234,7 +246,7 @@ void OperationalDeviceProxy::HandleCASEConnected(void * context, CASEClient * cl
     }
     else
     {
-        device->mState = State::SecureConnected;
+        device->MoveToState(State::SecureConnected);
 
         device->DequeueConnectionFailureCallbacks(CHIP_NO_ERROR, /* executeCallback */ false);
         device->DequeueConnectionSuccessCallbacks(/* executeCallback */ true);
@@ -249,7 +261,7 @@ CHIP_ERROR OperationalDeviceProxy::Disconnect()
     {
         mInitParams.sessionManager->ExpirePairing(mSecureSession.Get());
     }
-    mState = State::Initialized;
+    MoveToState(State::Initialized);
     if (mCASEClient)
     {
         mInitParams.clientPool->Release(mCASEClient);
@@ -261,7 +273,7 @@ CHIP_ERROR OperationalDeviceProxy::Disconnect()
 void OperationalDeviceProxy::SetConnectedSession(const SessionHandle & handle)
 {
     mSecureSession.Grab(handle);
-    mState = State::SecureConnected;
+    MoveToState(State::SecureConnected);
 }
 
 void OperationalDeviceProxy::Clear()
@@ -272,7 +284,7 @@ void OperationalDeviceProxy::Clear()
         mCASEClient = nullptr;
     }
 
-    mState      = State::Uninitialized;
+    MoveToState(State::Uninitialized);
     mInitParams = DeviceProxyInitParams();
 }
 
@@ -287,7 +299,7 @@ void OperationalDeviceProxy::CloseCASESession()
 
 void OperationalDeviceProxy::OnSessionReleased()
 {
-    mState = State::Initialized;
+    MoveToState(State::Initialized);
 }
 
 CHIP_ERROR OperationalDeviceProxy::ShutdownSubscriptions()

src/app/OperationalDeviceProxy.h

@@ -213,6 +213,8 @@ class DLL_EXPORT OperationalDeviceProxy : public DeviceProxy, SessionReleaseDele
 
     Transport::PeerAddress mDeviceAddress = Transport::PeerAddress::UDP(Inet::IPAddress::Any);
 
+    void MoveToState(State aTargetState);
+
     State mState = State::Uninitialized;
 
     SessionHolderWithDelegate mSecureSession;

src/controller/AutoCommissioner.cpp

@@ -97,6 +97,14 @@ CHIP_ERROR AutoCommissioner::SetCommissioningParameters(const CommissioningParam
 }
 
 CommissioningStage AutoCommissioner::GetNextCommissioningStage(CommissioningStage currentStage, CHIP_ERROR & lastErr)
+{
+    auto nextStage = _GetNextCommissioningStage(currentStage, lastErr);
+    ChipLogProgress(Controller, "Going from commissioning step '%s' with lastErr = '%s' --> '%s'", StageToString(currentStage),
+                    lastErr.AsString(), StageToString(nextStage));
+    return nextStage;
+}
+
+CommissioningStage AutoCommissioner::_GetNextCommissioningStage(CommissioningStage currentStage, CHIP_ERROR & lastErr)
 {
     if (lastErr != CHIP_NO_ERROR)
     {
@@ -287,6 +295,100 @@ CHIP_ERROR AutoCommissioner::NOCChainGenerated(ByteSpan noc, ByteSpan icac, Byte
     return CHIP_NO_ERROR;
 }
 
+const char * AutoCommissioner::StageToString(CommissioningStage stage)
+{
+    switch (stage)
+    {
+    case kError:
+        return "Error";
+        break;
+
+    case kSecurePairing:
+        return "SecurePairing";
+        break;
+
+    case kArmFailsafe:
+        return "ArmFailSafe";
+        break;
+
+    case kGetNetworkTechnology:
+        return "GetNetworkTechnology";
+        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;
+
+    case kConfigACL:
+        return "ConfigACL";
+        break;
+
+    default:
+        return "???";
+        break;
+    }
+}
+
 CHIP_ERROR AutoCommissioner::CommissioningStepFinished(CHIP_ERROR err, CommissioningDelegate::CommissioningReport report)
 {
     if (err != CHIP_NO_ERROR)
@@ -295,6 +397,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::kGetNetworkTechnology:

src/controller/AutoCommissioner.h

@@ -36,9 +36,11 @@ class AutoCommissioner : public CommissioningDelegate
     virtual CHIP_ERROR StartCommissioning(DeviceCommissioner * commissioner, CommissioneeDeviceProxy * proxy) override;
 
     virtual CHIP_ERROR CommissioningStepFinished(CHIP_ERROR err, CommissioningDelegate::CommissioningReport report) override;
+    static const char * StageToString(CommissioningStage stage);
 
 private:
     CommissioningStage GetNextCommissioningStage(CommissioningStage currentStage, CHIP_ERROR & lastErr);
+    CommissioningStage _GetNextCommissioningStage(CommissioningStage currentStage, CHIP_ERROR & lastErr);
     void ReleaseDAC();
     void ReleasePAI();
 

src/controller/CHIPDeviceController.cpp

@@ -1501,12 +1501,13 @@ void DeviceCommissioner::CommissioningStageComplete(CHIP_ERROR err, Commissionin
 #if CHIP_DEVICE_CONFIG_ENABLE_DNSSD
 void DeviceCommissioner::OnNodeIdResolved(const chip::Dnssd::ResolvedNodeData & nodeData)
 {
-    ChipLogProgress(Controller, "OperationalDiscoveryComplete for device ID 0x" ChipLogFormatX64,
-                    ChipLogValueX64(nodeData.mPeerId.GetNodeId()));
+    ChipLogProgress(Controller, "F" ChipLogFormatX64 ": OperationalDiscoveryComplete for device ID N" ChipLogFormatX64,
+                    ChipLogValueX64(mFabricId), ChipLogValueX64(nodeData.mPeerId.GetNodeId()));
     VerifyOrReturn(mState == State::Initialized);
 
     mDNSCache.Insert(nodeData);
 
+    mCASESessionManager->FindOrEstablishSession(nodeData.mPeerId, &mOnDeviceConnectedCallback, &mOnDeviceConnectionFailureCallback);
     mCASESessionManager->FindOrEstablishSession(nodeData.mPeerId, &mOnDeviceConnectedCallback, &mOnDeviceConnectionFailureCallback);
     DeviceController::OnNodeIdResolved(nodeData);
 }
@@ -1649,6 +1650,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'",
+                    AutoCommissioner::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;

src/lib/support/logging/CHIPLogging.cpp

@@ -96,6 +96,7 @@ static const char ModuleNames[] = "-\0\0" // None
                                   "TST"   // Test
                                   "ODP"   // OperationalDeviceProxy
                                   "ATM"   // Automation
+                                  "CSM"   // CASESessionManager
     ;
 
 #define ModuleNamesCount ((sizeof(ModuleNames) - 1) / chip::Logging::kMaxModuleNameLen)

src/lib/support/logging/Constants.h

@@ -58,6 +58,7 @@ enum LogModule
     kLogModule_Test,
     kLogModule_OperationalDeviceProxy,
     kLogModule_Automation,
+    kLogModule_CASESessionManager,
 
     kLogModule_Max
 };