diff --git a/src/app/CASESessionManager.cpp b/src/app/CASESessionManager.cpp index af580d35148ee7..92c67a6b8f6f49 100644 --- 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 index 95edcadc4ec0fe..4aad213124c966 100644 --- 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 * onConnection, Callback::Callback * 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 index c976bde994b525..74806c4a57a4cc 100644 --- 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 index 4e176ac8bf4934..763d92939a8ad8 100644 --- 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 index fa4693adf2152c..82dd12fd4cbcc6 100644 --- 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 index ece90d3921420d..f9e1a31eee6e32 100644 --- 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 index 0d66b3ec6f6e59..36890f85cca211 100644 --- 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 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(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 new file mode 100644 index 00000000000000..9038af9402679f --- /dev/null +++ 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 + +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 index 4eb1825aeb36fb..c662ee7f22168d 100644 --- 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 index b1dd1fc32f2f37..d68b07ac436671 100644 --- 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 index c09b0f36d1a70b..8984790d9f9326 100644 --- 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 index 78834aecc065ee..92130e2e21772a 100644 --- 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 index 19c24e81eb6f66..3cbd9e7acdf946 100644 --- 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 index 0214fcaa2dbab8..ec2c47aba9cff3 100644 --- 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 };