Add more prints to AutoCommissioner/CASESessionManager

src/app/CASESessionManager.cpp

@@ -44,9 +44,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)
         {

src/app/OperationalDeviceProxy.cpp

@@ -42,6 +42,17 @@ using namespace chip::Callback;
 
 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,
                                            Dnssd::ResolverProxy * resolver)
@@ -116,8 +127,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);
@@ -161,7 +172,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;
 }
@@ -220,7 +231,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);
@@ -241,7 +252,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);
@@ -256,7 +267,7 @@ CHIP_ERROR OperationalDeviceProxy::Disconnect()
     {
         mInitParams.sessionManager->ExpirePairing(mSecureSession.Get());
     }
-    mState = State::Initialized;
+    MoveToState(State::Initialized);
     if (mCASEClient)
     {
         mInitParams.clientPool->Release(mCASEClient);
@@ -268,7 +279,7 @@ CHIP_ERROR OperationalDeviceProxy::Disconnect()
 void OperationalDeviceProxy::SetConnectedSession(const SessionHandle & handle)
 {
     mSecureSession.Grab(handle);
-    mState = State::SecureConnected;
+    MoveToState(State::SecureConnected);
 }
 
 void OperationalDeviceProxy::Clear()
@@ -279,7 +290,7 @@ void OperationalDeviceProxy::Clear()
         mCASEClient = nullptr;
     }
 
-    mState      = State::Uninitialized;
+    MoveToState(State::Uninitialized);
     mInitParams = DeviceProxyInitParams();
 }
 
@@ -294,7 +305,7 @@ void OperationalDeviceProxy::CloseCASESession()
 
 void OperationalDeviceProxy::OnSessionReleased()
 {
-    mState = State::Initialized;
+    MoveToState(State::Initialized);
 }
 
 CHIP_ERROR OperationalDeviceProxy::ShutdownSubscriptions()

src/app/OperationalDeviceProxy.h

@@ -225,6 +225,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

@@ -102,6 +102,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)
     {
@@ -323,6 +331,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:

src/controller/AutoCommissioner.h

@@ -39,6 +39,7 @@ class AutoCommissioner : public CommissioningDelegate
 
 private:
     CommissioningStage GetNextCommissioningStage(CommissioningStage currentStage, CHIP_ERROR & lastErr);
+    CommissioningStage _GetNextCommissioningStage(CommissioningStage currentStage, CHIP_ERROR & lastErr);
     void ReleaseDAC();
     void ReleasePAI();
 

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",

src/controller/CHIPDeviceController.cpp

@@ -1446,7 +1446,9 @@ void DeviceCommissioner::CommissioningStageComplete(CHIP_ERROR err, Commissionin
 
 void DeviceCommissioner::OnOperationalNodeResolved(const chip::Dnssd::ResolvedNodeData & nodeData)
 {
-    ChipLogProgress(Controller, "OperationalDiscoveryComplete for device ID 0x" ChipLogFormatX64,
+    ChipLogProgress(Controller,
+                    "[" ChipLogFormatX64 "] OperationalDiscoveryComplete for device " ChipLogFormatX64 ":" ChipLogFormatX64,
+                    ChipLogValueX64(mFabricId), ChipLogValueX64(nodeData.mPeerId.GetCompressedFabricId()),
                     ChipLogValueX64(nodeData.mPeerId.GetNodeId()));
     VerifyOrReturn(mState == State::Initialized);
 
@@ -1751,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;
@@ -1995,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;
@@ -2010,7 +2014,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;
@@ -2025,7 +2028,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;
@@ -2039,7 +2041,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;
@@ -2057,7 +2058,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;
@@ -2075,14 +2075,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());

src/controller/CommissioningDelegate.cpp

@@ -0,0 +1,115 @@
+/*
+ *
+ *    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;
+
+    case kConfigACL:
+        return "ConfigACL";
+        break;
+
+    default:
+        return "???";
+        break;
+    }
+}
+
+} // namespace Controller
+} // namespace chip

src/controller/CommissioningDelegate.h

@@ -55,6 +55,8 @@ enum CommissioningStage : uint8_t
     kConfigACL,
 };
 
+const char * StageToString(CommissioningStage stage);
+
 struct WiFiCredentials
 {
     ByteSpan ssid;

src/lib/dnssd/Discovery_ImplPlatform.cpp

@@ -643,6 +643,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;

src/lib/dnssd/Resolver.h

@@ -73,7 +73,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);

src/lib/dnssd/Resolver_ImplMinimalMdns.cpp

@@ -691,6 +691,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);
 }

src/lib/support/logging/CHIPLogging.cpp

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