diff --git a/examples/fabric-bridge-app/linux/main.cpp b/examples/fabric-bridge-app/linux/main.cpp index d2350cad37c717..d639cea1ca0697 100644 --- a/examples/fabric-bridge-app/linux/main.cpp +++ b/examples/fabric-bridge-app/linux/main.cpp @@ -26,6 +26,7 @@ #include #include #include +#include #include #include #include @@ -39,16 +40,14 @@ #include #include -#include -#include - #include "CommissionableInit.h" #include "Device.h" -#include #include #include #include +#include +#include using namespace chip; using namespace chip::app; @@ -58,12 +57,41 @@ using namespace chip::Transport; using namespace chip::DeviceLayer; using namespace chip::app::Clusters; +#define POLL_INTERVAL_MS (100) + namespace { EndpointId gCurrentEndpointId; EndpointId gFirstDynamicEndpointId; Device * gDevices[CHIP_DEVICE_CONFIG_DYNAMIC_ENDPOINT_COUNT + 1]; +bool KeyboardHit() +{ + int bytesWaiting; + ioctl(0, FIONREAD, &bytesWaiting); + return bytesWaiting > 0; +} + +void BridgePollingThread() +{ + while (true) + { + if (KeyboardHit()) + { + int ch = getchar(); + if (ch == 'e') + { + ChipLogProgress(DeviceLayer, "Exiting....."); + exit(0); + } + continue; + } + + // Sleep to avoid tight loop reading commands + usleep(POLL_INTERVAL_MS * 1000); + } +} + } // namespace // REVISION DEFINITIONS: @@ -245,42 +273,6 @@ Protocols::InteractionModel::Status emberAfExternalAttributeWriteCallback(Endpoi return ret; } -#define POLL_INTERVAL_MS (100) -uint8_t poll_prescale = 0; - -bool kbhit() -{ - int byteswaiting; - ioctl(0, FIONREAD, &byteswaiting); - return byteswaiting > 0; -} - -const int16_t oneDegree = 100; - -void * bridge_polling_thread(void * context) -{ - while (true) - { - if (kbhit()) - { - int ch = getchar(); - - // Commands used for the actions bridge test plan. - if (ch == 'e') - { - ChipLogProgress(DeviceLayer, "Exiting....."); - exit(0); - } - continue; - } - - // Sleep to avoid tight loop reading commands - usleep(POLL_INTERVAL_MS * 1000); - } - - return nullptr; -} - void ApplicationInit() { // Clear out the device database @@ -292,15 +284,9 @@ void ApplicationInit() static_cast(emberAfEndpointFromIndex(static_cast(emberAfFixedEndpointCount() - 1))) + 1); gCurrentEndpointId = gFirstDynamicEndpointId; - { - pthread_t poll_thread; - int res = pthread_create(&poll_thread, nullptr, bridge_polling_thread, nullptr); - if (res) - { - printf("Error creating polling thread: %d\n", res); - exit(1); - } - } + // Start a thread for bridge polling + std::thread pollingThread(BridgePollingThread); + pollingThread.detach(); } void ApplicationShutdown() {} diff --git a/examples/tv-casting-app/android/App/app/src/main/jni/cpp/core/MatterCastingPlayer-JNI.cpp b/examples/tv-casting-app/android/App/app/src/main/jni/cpp/core/MatterCastingPlayer-JNI.cpp index d0409c6a27945c..b2597c883406d8 100644 --- a/examples/tv-casting-app/android/App/app/src/main/jni/cpp/core/MatterCastingPlayer-JNI.cpp +++ b/examples/tv-casting-app/android/App/app/src/main/jni/cpp/core/MatterCastingPlayer-JNI.cpp @@ -120,9 +120,8 @@ JNI_METHOD(jobject, verifyOrEstablishConnection) matter::casting::core::ConnectionCallbacks connectionCallbacks; connectionCallbacks.mOnConnectionComplete = connectCallback; - // TODO: Verify why commissioningWindowTimeoutSec is a "unsigned long long int" type. Seems too big. - castingPlayer->VerifyOrEstablishConnection(connectionCallbacks, - static_cast(commissioningWindowTimeoutSec), idOptions); + castingPlayer->VerifyOrEstablishConnection(connectionCallbacks, static_cast(commissioningWindowTimeoutSec), + idOptions); return support::convertMatterErrorFromCppToJava(CHIP_NO_ERROR); } diff --git a/examples/tv-casting-app/linux/simple-app-helper.cpp b/examples/tv-casting-app/linux/simple-app-helper.cpp index 49f006aa9cf4ab..beef624eea5ff8 100644 --- a/examples/tv-casting-app/linux/simple-app-helper.cpp +++ b/examples/tv-casting-app/linux/simple-app-helper.cpp @@ -33,6 +33,11 @@ // VendorId of the Endpoint on the CastingPlayer that the CastingApp desires to interact with after connection const uint16_t kDesiredEndpointVendorId = 65521; +// EndpointId of the Endpoint on the CastingPlayer that the CastingApp desires to interact with after connection using the +// Commissioner-Generated passcode commissioning flow +const uint8_t kDesiredEndpointId = 1; +// Indicates that the Commissioner-Generated passcode commissioning flow is in progress. +bool gCommissionerGeneratedPasscodeFlowRunning = false; DiscoveryDelegateImpl * DiscoveryDelegateImpl::_discoveryDelegateImpl = nullptr; bool gAwaitingCommissionerPasscodeInput = false; @@ -244,6 +249,16 @@ CHIP_ERROR InitCommissionableDataProvider(LinuxCommissionableDataProvider & prov options.payload.discriminator.GetLongValue()); } +void LogEndpointsDetails(const std::vector> & endpoints) +{ + ChipLogProgress(AppServer, "simple-app-helper.cpp::LogEndpointsDetails() Number of Endpoints: %d", + static_cast(endpoints.size())); + for (const auto & endpoint : endpoints) + { + endpoint->LogDetail(); + } +} + void ConnectionHandler(CHIP_ERROR err, matter::casting::core::CastingPlayer * castingPlayer) { ChipLogProgress(AppServer, "simple-app-helper.cpp::ConnectionHandler()"); @@ -256,16 +271,39 @@ void ConnectionHandler(CHIP_ERROR err, matter::casting::core::CastingPlayer * ca "simple-app-helper.cpp::ConnectionHandler(): Failed to connect to CastingPlayer (ID: %s) with err %" CHIP_ERROR_FORMAT, targetCastingPlayer->GetId(), err.Format())); - ChipLogProgress(AppServer, "simple-app-helper.cpp::ConnectionHandler(): Successfully connected to CastingPlayer (ID: %s)", - castingPlayer->GetId()); - ChipLogProgress(AppServer, - "simple-app-helper.cpp::ConnectionHandler(): Triggering demo interactions with CastingPlayer (ID: %s)", - castingPlayer->GetId()); + if (gCommissionerGeneratedPasscodeFlowRunning) + { + ChipLogProgress(AppServer, + "simple-app-helper.cpp::ConnectionHandler(): Successfully connected to CastingPlayer (ID: %s) using " + "Commissioner-Generated passcode", + castingPlayer->GetId()); + ChipLogProgress(AppServer, "simple-app-helper.cpp::ConnectionHandler(): Desired Endpoint ID for demo interactions: 1"); + } + else + { + ChipLogProgress(AppServer, "simple-app-helper.cpp::ConnectionHandler(): Successfully connected to CastingPlayer (ID: %s)", + castingPlayer->GetId()); + ChipLogProgress(AppServer, + "simple-app-helper.cpp::ConnectionHandler(): Desired Endpoint Vendor ID for demo interactions: %d", + kDesiredEndpointVendorId); + } + ChipLogProgress(AppServer, "simple-app-helper.cpp::ConnectionHandler(): Getting endpoints avaiable for demo interactions"); std::vector> endpoints = castingPlayer->GetEndpoints(); + LogEndpointsDetails(endpoints); + // Find the desired Endpoint and auto-trigger some Matter Casting demo interactions auto it = std::find_if(endpoints.begin(), endpoints.end(), [](const matter::casting::memory::Strong & endpoint) { + if (gCommissionerGeneratedPasscodeFlowRunning) + { + // For the example Commissioner-Generated passcode commissioning flow, run demo interactions with + // the Endpoint with ID 1. For this flow, we commissioned with the Target Content Application + // with Vendor ID 1111. Since this target content application does not report its Endpoint's + // Vendor IDs, we find the desired endpoint based on the Endpoint ID. See + // connectedhomeip/examples/tv-app/tv-common/include/AppTv.h. + return endpoint->GetId() == kDesiredEndpointId; + } return endpoint->GetVendorId() == kDesiredEndpointVendorId; }); if (it != endpoints.end()) @@ -273,6 +311,11 @@ void ConnectionHandler(CHIP_ERROR err, matter::casting::core::CastingPlayer * ca // The desired endpoint is endpoints[index] unsigned index = (unsigned int) std::distance(endpoints.begin(), it); + ChipLogProgress( + AppServer, + "simple-app-helper.cpp::ConnectionHandler(): Triggering demo interactions with CastingPlayer (ID: %s). Endpoint ID: %d", + castingPlayer->GetId(), endpoints[index]->GetId()); + // demonstrate invoking a command InvokeContentLauncherLaunchURL(endpoints[index]); @@ -286,8 +329,8 @@ void ConnectionHandler(CHIP_ERROR err, matter::casting::core::CastingPlayer * ca { ChipLogError( AppServer, - "simple-app-helper.cpp::ConnectionHandler():Desired Endpoint Vendor Id (%d) not found on the CastingPlayer (ID: %s)", - kDesiredEndpointVendorId, castingPlayer->GetId()); + "simple-app-helper.cpp::ConnectionHandler():Desired Endpoint Vendor ID not found on the CastingPlayer (ID: %s)", + castingPlayer->GetId()); } } @@ -350,9 +393,14 @@ CHIP_ERROR CommandHandler(int argc, char ** argv) ChipLogError(AppServer, "Invalid casting player index provided: %lu", index)); targetCastingPlayer = castingPlayers.at(index); + gCommissionerGeneratedPasscodeFlowRunning = false; matter::casting::core::IdentificationDeclarationOptions idOptions; + chip::Protocols::UserDirectedCommissioning::TargetAppInfo targetAppInfo; + targetAppInfo.vendorId = kDesiredEndpointVendorId; + if (argc == 3) { + if (strcmp(argv[2], "commissioner-generated-passcode") == 0) { // Attempt Commissioner-Generated Passcode (commissioner-generated-passcode) commissioning flow only if the @@ -364,6 +412,14 @@ CHIP_ERROR CommandHandler(int argc, char ** argv) "Commissioner-Generated Passcode commissioning flow", index); idOptions.mCommissionerPasscode = true; + + // For the example Commissioner-Generated passcode commissioning flow, override the default Target Content + // Application Vendor ID, which is configured on the tv-app. This Target Content Application Vendor ID (1111), + // does not implement the AccountLogin cluster, which would otherwise auto commission using the + // Commissionee-Generated passcode upon recieving the IdentificationDeclaration Message. See + // connectedhomeip/examples/tv-app/tv-common/include/AppTv.h. + targetAppInfo.vendorId = 1111; + gCommissionerGeneratedPasscodeFlowRunning = true; } else { @@ -374,9 +430,8 @@ CHIP_ERROR CommandHandler(int argc, char ** argv) } } } - chip::Protocols::UserDirectedCommissioning::TargetAppInfo targetAppInfo; - targetAppInfo.vendorId = kDesiredEndpointVendorId; - CHIP_ERROR result = idOptions.addTargetAppInfo(targetAppInfo); + + CHIP_ERROR result = idOptions.addTargetAppInfo(targetAppInfo); if (result != CHIP_NO_ERROR) { ChipLogError(AppServer, "CommandHandler() request, failed to add targetAppInfo: %" CHIP_ERROR_FORMAT, result.Format()); @@ -430,11 +485,8 @@ CHIP_ERROR CommandHandler(int argc, char ** argv) err.Format()); } - matter::casting::core::ConnectionCallbacks connectionCallbacks; - connectionCallbacks.mOnConnectionComplete = ConnectionHandler; - // Continue Connecting to the target CastingPlayer with the user entered Commissioner-generated Passcode. - targetCastingPlayer->ContinueConnecting(connectionCallbacks, matter::casting::core::kCommissioningWindowTimeoutSec); + targetCastingPlayer->ContinueConnecting(); } else { diff --git a/examples/tv-casting-app/tv-casting-common/core/CastingPlayer.cpp b/examples/tv-casting-app/tv-casting-common/core/CastingPlayer.cpp index b3075be95304d8..ff204923da5d40 100644 --- a/examples/tv-casting-app/tv-casting-common/core/CastingPlayer.cpp +++ b/examples/tv-casting-app/tv-casting-common/core/CastingPlayer.cpp @@ -29,9 +29,7 @@ namespace core { CastingPlayer * CastingPlayer::mTargetCastingPlayer = nullptr; -// TODO: Verify why commissioningWindowTimeoutSec is a "unsigned long long int" type. Seems too big. -void CastingPlayer::VerifyOrEstablishConnection(ConnectionCallbacks connectionCallbacks, - unsigned long long int commissioningWindowTimeoutSec, +void CastingPlayer::VerifyOrEstablishConnection(ConnectionCallbacks connectionCallbacks, uint16_t commissioningWindowTimeoutSec, IdentificationDeclarationOptions idOptions) { ChipLogProgress(AppServer, "CastingPlayer::VerifyOrEstablishConnection() called"); @@ -72,6 +70,25 @@ void CastingPlayer::VerifyOrEstablishConnection(ConnectionCallbacks connectionCa "CastingPlayer::VerifyOrEstablishConnection() CommissionerDeclarationCallback not provided in ConnectionCallbacks"); } + ChipLogProgress(AppServer, "CastingPlayer::VerifyOrEstablishConnection() verifying User Directed Commissioning (UDC) state"); + mIdOptions.LogDetail(); + if (!GetSupportsCommissionerGeneratedPasscode() && mIdOptions.mCommissionerPasscode) + { + ChipLogError(AppServer, + "CastingPlayer::VerifyOrEstablishConnection() the target CastingPlayer doesn't support Commissioner-Generated " + "passcode yet IdentificationDeclarationOptions.mCommissionerPasscode is set to true"); + SuccessOrExit(err = CHIP_ERROR_INVALID_ARGUMENT); + } + if (!matter::casting::core::CommissionerDeclarationHandler::GetInstance()->HasCommissionerDeclarationCallback() && + mIdOptions.mCommissionerPasscode) + { + ChipLogError( + AppServer, + "CastingPlayer::VerifyOrEstablishConnection() the CommissionerDeclarationHandler CommissionerDeclaration message " + "callback has not been set, yet IdentificationDeclarationOptions.mCommissionerPasscode is set to true"); + SuccessOrExit(err = CHIP_ERROR_INVALID_ARGUMENT); + } + // If *this* CastingPlayer was previously connected to, its nodeId, fabricIndex and other attributes should be present // in the CastingStore cache. If that is the case, AND, the cached data contains the endpoint desired by the client, if any, // as per IdentificationDeclarationOptions.mTargetAppInfos, simply Find or Re-establish the CASE session and return early. @@ -138,28 +155,11 @@ void CastingPlayer::VerifyOrEstablishConnection(ConnectionCallbacks connectionCa } else { - ChipLogProgress(AppServer, - "CastingPlayer::VerifyOrEstablishConnection() verifying User Directed Commissioning (UDC) state"); - mIdOptions.LogDetail(); - SuccessOrExit(err = support::ChipDeviceEventHandler::SetUdcStatus(true)); - - if (!GetSupportsCommissionerGeneratedPasscode() && mIdOptions.mCommissionerPasscode) - { - ChipLogError( - AppServer, - "CastingPlayer::VerifyOrEstablishConnection() the target CastingPlayer doesn't support Commissioner-Generated " - "passcode yet IdentificationDeclarationOptions.mCommissionerPasscode is set to true"); - SuccessOrExit(err = CHIP_ERROR_INVALID_ARGUMENT); - } - if (!matter::casting::core::CommissionerDeclarationHandler::GetInstance()->HasCommissionerDeclarationCallback() && - mIdOptions.mCommissionerPasscode) - { - ChipLogError(AppServer, - "CastingPlayer::VerifyOrEstablishConnection() the CommissionerDeclaration message callback has not been " - "set yet IdentificationDeclarationOptions.mCommissionerPasscode is set to true"); - SuccessOrExit(err = CHIP_ERROR_INVALID_ARGUMENT); - } - + // We need to call OpenBasicCommissioningWindow() for both Commissionee-Generated passcode commissioning flow and + // Commissioner-Generated passcode commissioning flow. Per the Matter spec (UserDirectedCommissioning), even if the + // Commissionee sends an IdentificationDeclaration with CommissionerPasscode set to true, the Commissioner will first + // attempt to use AccountLogin in order to obtain Passcode using rotatingID. If no Passcode is obtained, Commissioner + // displays a Passcode. ChipLogProgress(AppServer, "CastingPlayer::VerifyOrEstablishConnection() calling OpenBasicCommissioningWindow()"); SuccessOrExit(err = chip::Server::GetInstance().GetCommissioningWindowManager().OpenBasicCommissioningWindow( chip::System::Clock::Seconds16(mCommissioningWindowTimeoutSec))); @@ -178,33 +178,19 @@ void CastingPlayer::VerifyOrEstablishConnection(ConnectionCallbacks connectionCa } } -void CastingPlayer::ContinueConnecting(ConnectionCallbacks connectionCallbacks, - unsigned long long int commissioningWindowTimeoutSec) +void CastingPlayer::ContinueConnecting() { ChipLogProgress(AppServer, "CastingPlayer::ContinueConnecting()"); CHIP_ERROR err = CHIP_NO_ERROR; - SuccessOrExit(err = support::ChipDeviceEventHandler::SetUdcStatus(true)); - VerifyOrExit( - connectionCallbacks.mOnConnectionComplete != nullptr, - ChipLogError(AppServer, "CastingPlayer::ContinueConnecting() ConnectionCallbacks.mOnConnectionComplete was not provided")); - mConnectionState = CASTING_PLAYER_CONNECTING; - mOnCompleted = connectionCallbacks.mOnConnectionComplete; - mCommissioningWindowTimeoutSec = commissioningWindowTimeoutSec; - mTargetCastingPlayer = this; - - // Register the handler for Commissioner's CommissionerDeclaration messages. The CommissionerDeclaration messages provide - // information indicating the Commissioner's pre-commissioning state. - if (connectionCallbacks.mCommissionerDeclarationCallback != nullptr) - { - matter::casting::core::CommissionerDeclarationHandler::GetInstance()->SetCommissionerDeclarationCallback( - connectionCallbacks.mCommissionerDeclarationCallback); - } - else + // Verify that mOnCompleted is not nullptr. + VerifyOrExit(mOnCompleted != nullptr, ChipLogError(AppServer, "CastingPlayer::ContinueConnecting() mOnCompleted == nullptr")); + if (!matter::casting::core::CommissionerDeclarationHandler::GetInstance()->HasCommissionerDeclarationCallback()) { - ChipLogProgress( - AppServer, - "CastingPlayer::VerifyOrEstablishConnection() CommissionerDeclarationCallback not provided in ConnectionCallbacks"); + ChipLogProgress(AppServer, + "CastingPlayer::ContinueConnecting() CommissionerDeclaration message callback has not been set."); } + mConnectionState = CASTING_PLAYER_CONNECTING; + mTargetCastingPlayer = this; ChipLogProgress(AppServer, "CastingPlayer::ContinueConnecting() calling OpenBasicCommissioningWindow()"); SuccessOrExit(err = chip::Server::GetInstance().GetCommissioningWindowManager().OpenBasicCommissioningWindow( @@ -272,6 +258,8 @@ CHIP_ERROR CastingPlayer::SendUserDirectedCommissioningRequest() chip::Protocols::UserDirectedCommissioning::IdentificationDeclaration id = mIdOptions.buildIdentificationDeclarationMessage(); + ReturnErrorOnFailure(support::ChipDeviceEventHandler::SetUdcStatus(true)); + ReturnErrorOnFailure(chip::Server::GetInstance().SendUserDirectedCommissioningRequest( chip::Transport::PeerAddress::UDP(*ipAddressToUse, mAttributes.port, mAttributes.interfaceId), id)); @@ -401,6 +389,26 @@ void CastingPlayer::LogDetail() const } } +CastingPlayer::CastingPlayer(const CastingPlayer & other) : + std::enable_shared_from_this(other), mEndpoints(other.mEndpoints), mConnectionState(other.mConnectionState), + mAttributes(other.mAttributes), mIdOptions(other.mIdOptions), + mCommissioningWindowTimeoutSec(other.mCommissioningWindowTimeoutSec), mOnCompleted(other.mOnCompleted) +{} + +CastingPlayer & CastingPlayer::operator=(const CastingPlayer & other) +{ + if (this != &other) + { + mAttributes = other.mAttributes; + mEndpoints = other.mEndpoints; + mConnectionState = other.mConnectionState; + mIdOptions = other.mIdOptions; + mCommissioningWindowTimeoutSec = other.mCommissioningWindowTimeoutSec; + mOnCompleted = other.mOnCompleted; + } + return *this; +} + ConnectionContext::ConnectionContext(void * clientContext, core::CastingPlayer * targetCastingPlayer, chip::OnDeviceConnected onDeviceConnectedFn, chip::OnDeviceConnectionFailure onDeviceConnectionFailureFn) diff --git a/examples/tv-casting-app/tv-casting-common/core/CastingPlayer.h b/examples/tv-casting-app/tv-casting-common/core/CastingPlayer.h index 14a55e045fcb83..d5bbcd46006920 100644 --- a/examples/tv-casting-app/tv-casting-common/core/CastingPlayer.h +++ b/examples/tv-casting-app/tv-casting-common/core/CastingPlayer.h @@ -38,8 +38,8 @@ namespace core { const int kPortMaxLength = 5; // port is uint16_t // +1 for the : between the hostname and the port. -const int kIdMaxLength = chip::Dnssd::kHostNameMaxLength + kPortMaxLength + 1; -const unsigned long long int kCommissioningWindowTimeoutSec = 3 * 60; // 3 minutes +const int kIdMaxLength = chip::Dnssd::kHostNameMaxLength + kPortMaxLength + 1; +const uint16_t kCommissioningWindowTimeoutSec = 3 * 60; // 3 minutes /** * @brief Describes an Endpoint that the client wants to connect to @@ -111,46 +111,81 @@ class CastingPlayer : public std::enable_shared_from_this return (compareResult == 0) ? 1 : 0; } + /** + * @brief Define the copy constructor + */ + CastingPlayer(const CastingPlayer & other); + + /** + * @brief Define the assignment operator + */ + CastingPlayer & operator=(const CastingPlayer & other); + /** * @return true if this CastingPlayer is connected to the CastingApp */ bool IsConnected() const { return mConnectionState == CASTING_PLAYER_CONNECTED; } /** - * @brief Verifies that a connection exists with this CastingPlayer, or triggers a new session - * request. If the CastingApp does not have the nodeId and fabricIndex of this CastingPlayer cached on disk, - * this will execute the User Directed Commissioning (UDC) process. + * @brief Verifies that a connection exists with this CastingPlayer, or triggers a new commissioning session request. If the + * CastingApp does not have the nodeId and fabricIndex of this CastingPlayer cached on disk, this will execute the User Directed + * Commissioning (UDC) process by sending an IdentificationDeclaration message to the Commissioner. For certain UDC features, + * where a Commissioner reply is expected, this API needs to be followed up with the ContinueConnecting() API defiend below. See + * the Matter UDC specification or parameter class definitions for details on features not included in the description below. + * + * @param connectionCallbacks contains the ConnectCallback (Required) and CommissionerDeclarationCallback (Optional) defiend in + * ConnectCallbacks.h. + * + * ConnectCallback: The callback called when the connection process has ended, regardless of whether it was successful or not. + * + * CommissionerDeclarationCallback: The callback called when the Commissionee receives a CommissionerDeclaration message from + * the Commissioner. This callback is needed to support UDC features where a reply from the Commissioner is expected. It + * provides information indicating the Commissioner’s pre-commissioning state. + * + * For example: During Commissioner-Generated passcode commissioning, the Commissioner replies with a CommissionerDeclaration + * message with PasscodeDialogDisplayed and CommissionerPasscode set to true. Given these Commissioner state details, the client + * is expected to perform some actions, detailed in the ContinueConnecting() API below, and then call the ContinueConnecting() + * API to complete the process. * - * @param connectionCallbacks contains the ConnectCallback and CommissionerDeclarationCallback (Optional). * @param commissioningWindowTimeoutSec (Optional) time (in sec) to keep the commissioning window open, if commissioning is * required. Needs to be >= kCommissioningWindowTimeoutSec. + * * @param idOptions (Optional) Parameters in the IdentificationDeclaration message sent by the Commissionee to the Commissioner. * These parameters specify the information relating to the requested commissioning session. + * + * For example: To invoke the Commissioner-Generated passcode commissioning flow, the client would call this API with + * IdentificationDeclarationOptions containing CommissionerPasscode set to true. See IdentificationDeclarationOptions.h for a + * complete list of optional parameters. + * * Furthermore, attributes (such as VendorId) describe the TargetApp that the client wants to interact with after commissioning. * If this value is passed in, VerifyOrEstablishConnection() will force UDC, in case the desired * TargetApp is not found in the on-device CastingStore. */ void VerifyOrEstablishConnection(ConnectionCallbacks connectionCallbacks, - unsigned long long int commissioningWindowTimeoutSec = kCommissioningWindowTimeoutSec, - IdentificationDeclarationOptions idOptions = IdentificationDeclarationOptions()); + uint16_t commissioningWindowTimeoutSec = kCommissioningWindowTimeoutSec, + IdentificationDeclarationOptions idOptions = IdentificationDeclarationOptions()); /** - * @brief Continues the UDC process during the Commissioner-Generated passcode commissioning flow by sending a second - * IdentificationDeclaration to Commissioner containing CommissionerPasscode and CommissionerPasscodeReady set to true. At this - * point it is assumed that the following have occurred: - * 1. Client has handled the Commissioner's CommissionerDecelration message with PasscodeDialogDisplayed and - * CommissionerPasscode set to true. - * 2. Client prompted user to input Passcode from Commissioner. - * 3. Client has updated the commissioning session's PAKE verifier using the user input Passcode by updating the CastingApps + * @brief This is a continuation of the Commissioner-Generated passcode commissioning flow started via the + * VerifyOrEstablishConnection() API above. It continues the UDC process by sending a second IdentificationDeclaration message + * to Commissioner containing CommissionerPasscode and CommissionerPasscodeReady set to true. At this point it is assumed that + * the following have occurred: + * + * 1. Client (Commissionee) has sent the first IdentificationDeclaration message, via VerifyOrEstablishConnection(), to the + * Commissioner containing CommissionerPasscode set to true. + * 2. Commissioner generated and displayed a passcode. + * 3. The Commissioner replied with a CommissionerDecelration message with PasscodeDialogDisplayed and CommissionerPasscode set + * to true. + * 3. Client has handled the Commissioner's CommissionerDecelration message. + * 4. Client prompted user to input Passcode from Commissioner. + * 5. Client has updated the commissioning session's PAKE verifier using the user input Passcode by updating the CastingApps * CommissionableDataProvider * (matter::casting::core::CastingApp::GetInstance()->UpdateCommissionableDataProvider(CommissionableDataProvider)). * - * @param connectionCallbacks contains the ConnectCallback and CommissionerDeclarationCallback (Optional). - * @param commissioningWindowTimeoutSec (Optional) time (in sec) to keep the commissioning window open, if commissioning is - * required. Needs to be >= kCommissioningWindowTimeoutSec. + * The same connectionCallbacks and commissioningWindowTimeoutSec parameters passed into VerifyOrEstablishConnection() will be + * used. */ - void ContinueConnecting(ConnectionCallbacks connectionCallbacks, - unsigned long long int commissioningWindowTimeoutSec = kCommissioningWindowTimeoutSec); + void ContinueConnecting(); /** * @brief Sets the internal connection state of this CastingPlayer to "disconnected" @@ -220,8 +255,8 @@ class CastingPlayer : public std::enable_shared_from_this CastingPlayerAttributes mAttributes; IdentificationDeclarationOptions mIdOptions; static CastingPlayer * mTargetCastingPlayer; - unsigned long long int mCommissioningWindowTimeoutSec = kCommissioningWindowTimeoutSec; - ConnectCallback mOnCompleted = {}; + uint16_t mCommissioningWindowTimeoutSec = kCommissioningWindowTimeoutSec; + ConnectCallback mOnCompleted = {}; /** * @brief resets this CastingPlayer's state and calls mOnCompleted with the CHIP_ERROR. Also, after calling mOnCompleted, it diff --git a/examples/tv-casting-app/tv-casting-common/core/CommissionerDeclarationHandler.cpp b/examples/tv-casting-app/tv-casting-common/core/CommissionerDeclarationHandler.cpp index bb9ecc3c4c57d9..22e7d49cdb7a5d 100644 --- a/examples/tv-casting-app/tv-casting-common/core/CommissionerDeclarationHandler.cpp +++ b/examples/tv-casting-app/tv-casting-common/core/CommissionerDeclarationHandler.cpp @@ -38,7 +38,7 @@ CommissionerDeclarationHandler * CommissionerDeclarationHandler::GetInstance() } // TODO: In the following PRs. Implement setHandler() for CommissionerDeclaration messages and expose messages to higher layers for -// Linux(DONE), Android(pending) and iOS(pending). +// Linux, Android and iOS. void CommissionerDeclarationHandler::OnCommissionerDeclarationMessage( const chip::Transport::PeerAddress & source, chip::Protocols::UserDirectedCommissioning::CommissionerDeclaration cd) { diff --git a/examples/tv-casting-app/tv-casting-common/core/Endpoint.h b/examples/tv-casting-app/tv-casting-common/core/Endpoint.h index 4da8cd56210b07..fc18267cf466be 100644 --- a/examples/tv-casting-app/tv-casting-common/core/Endpoint.h +++ b/examples/tv-casting-app/tv-casting-common/core/Endpoint.h @@ -145,6 +145,12 @@ class Endpoint : public std::enable_shared_from_this } return nullptr; } + + void LogDetail() const + { + ChipLogProgress(AppServer, "Endpoint::LogDetail() Endpoint ID: %d, Vendor ID: %d, Product ID: %d", mAttributes.mId, + mAttributes.mVendorId, mAttributes.mProductId); + } }; }; // namespace core diff --git a/src/darwin/Framework/CHIP/MTRAsyncWorkQueue.mm b/src/darwin/Framework/CHIP/MTRAsyncWorkQueue.mm index 53a719502306bd..7220b6f72fc208 100644 --- a/src/darwin/Framework/CHIP/MTRAsyncWorkQueue.mm +++ b/src/darwin/Framework/CHIP/MTRAsyncWorkQueue.mm @@ -126,9 +126,9 @@ - (void)callReadyHandlerWithContext:(id)context completion:(MTRAsyncWorkCompleti auto readyHandler = _readyHandler; dispatch_async(_queue, ^{ if (!retryCount) { - MTR_LOG_DEFAULT("MTRAsyncWorkQueue<%@> executing work item [%llu]", context, uniqueID); + MTR_LOG("MTRAsyncWorkQueue<%@> executing work item [%llu]", context, uniqueID); } else { - MTR_LOG_DEFAULT("MTRAsyncWorkQueue<%@> executing work item [%llu] (retry %zd)", context, uniqueID, retryCount); + MTR_LOG("MTRAsyncWorkQueue<%@> executing work item [%llu] (retry %zd)", context, uniqueID, retryCount); } if (readyHandler) { readyHandler(context, retryCount, completion); @@ -268,9 +268,9 @@ - (void)enqueueWorkItem:(MTRAsyncWorkItem *)item // Logging the description once is enough because other log messages // related to the work item (execution, completion etc) can easily be // correlated using the unique id. - MTR_LOG_DEFAULT("MTRAsyncWorkQueue<%@, items count: %tu> enqueued work item [%llu]: %@", context.description, _items.count, item.uniqueID, description); + MTR_LOG("MTRAsyncWorkQueue<%@, items count: %tu> enqueued work item [%llu]: %@", context.description, _items.count, item.uniqueID, description); } else { - MTR_LOG_DEFAULT("MTRAsyncWorkQueue<%@, items count: %tu> enqueued work item [%llu]", context.description, _items.count, item.uniqueID); + MTR_LOG("MTRAsyncWorkQueue<%@, items count: %tu> enqueued work item [%llu]", context.description, _items.count, item.uniqueID); } [self _callNextReadyWorkItemWithContext:context]; @@ -280,7 +280,7 @@ - (void)invalidate { ContextSnapshot context(self); // outside of lock std::lock_guard lock(_lock); - MTR_LOG_INFO("MTRAsyncWorkQueue<%@> invalidate %tu items", context.description, _items.count); + MTR_LOG("MTRAsyncWorkQueue<%@> invalidate %tu items", context.description, _items.count); for (MTRAsyncWorkItem * item in _items) { [item cancel]; } @@ -309,14 +309,14 @@ - (void)_postProcessWorkItem:(MTRAsyncWorkItem *)workItem // already part of the running work items allowed by width - retry directly if (retry) { - MTR_LOG_DEFAULT("MTRAsyncWorkQueue<%@> retry needed for work item [%llu]", context.description, workItem.uniqueID); + MTR_LOG("MTRAsyncWorkQueue<%@> retry needed for work item [%llu]", context.description, workItem.uniqueID); [self _callWorkItem:workItem withContext:context]; return; } [workItem markComplete]; [_items removeObjectAtIndex:indexOfWorkItem]; - MTR_LOG_DEFAULT("MTRAsyncWorkQueue<%@, items count: %tu> completed work item [%llu]", context.description, _items.count, workItem.uniqueID); + MTR_LOG("MTRAsyncWorkQueue<%@, items count: %tu> completed work item [%llu]", context.description, _items.count, workItem.uniqueID); // sanity check running work item count is positive if (_runningWorkItemCount == 0) { @@ -398,11 +398,11 @@ - (void)_callNextReadyWorkItemWithContext:(ContextSnapshot const &)context case MTRNotBatched: goto done; // can't merge anything else case MTRBatchedPartially: - MTR_LOG_DEFAULT("MTRAsyncWorkQueue<%@> partially merged work item [%llu] into %llu", + MTR_LOG("MTRAsyncWorkQueue<%@> partially merged work item [%llu] into %llu", context.description, nextWorkItem.uniqueID, workItem.uniqueID); goto done; // can't merge anything else case MTRBatchedFully: - MTR_LOG_DEFAULT("MTRAsyncWorkQueue<%@> fully merged work item [%llu] into %llu", + MTR_LOG("MTRAsyncWorkQueue<%@> fully merged work item [%llu] into %llu", context.description, nextWorkItem.uniqueID, workItem.uniqueID); [_items removeObjectAtIndex:1]; continue; // try to batch the next item (if any) diff --git a/src/darwin/Framework/CHIP/MTRCertificates.mm b/src/darwin/Framework/CHIP/MTRCertificates.mm index 725a812ca49d40..5837a50a3fe21a 100644 --- a/src/darwin/Framework/CHIP/MTRCertificates.mm +++ b/src/darwin/Framework/CHIP/MTRCertificates.mm @@ -42,7 +42,7 @@ + (MTRCertificateDERBytes _Nullable)createRootCertificate:(id)keypai validityPeriod:(NSDateInterval *)validityPeriod error:(NSError * __autoreleasing *)error { - MTR_LOG_DEFAULT("Generating root certificate"); + MTR_LOG("Generating root certificate"); NSData * rootCert = nil; CHIP_ERROR err = MTROperationalCredentialsDelegate::GenerateRootCertificate(keypair, issuerID, fabricID, validityPeriod, &rootCert); @@ -74,7 +74,7 @@ + (MTRCertificateDERBytes _Nullable)createIntermediateCertificate:(id validityPeriod:(NSDateInterval *)validityPeriod error:(NSError * __autoreleasing _Nullable * _Nullable)error { - MTR_LOG_DEFAULT("Generating operational certificate"); + MTR_LOG("Generating operational certificate"); NSData * opcert = nil; CHIP_ERROR err = MTROperationalCredentialsDelegate::GenerateOperationalCertificate( signingKeypair, signingCertificate, operationalPublicKey, fabricID, nodeID, caseAuthenticatedTags, validityPeriod, &opcert); diff --git a/src/darwin/Framework/CHIP/MTRDevice.mm b/src/darwin/Framework/CHIP/MTRDevice.mm index 6e321c1a38d930..7cb816708aac49 100644 --- a/src/darwin/Framework/CHIP/MTRDevice.mm +++ b/src/darwin/Framework/CHIP/MTRDevice.mm @@ -486,7 +486,7 @@ - (void)_setTimeOnDevice auto dstOffsetsMaxSize = [self readAttributeWithEndpointID:dstOffsetsMaxSizePath.endpoint clusterID:dstOffsetsMaxSizePath.cluster attributeID:dstOffsetsMaxSizePath.attribute params:nil]; if (dstOffsetsMaxSize == nil) { // This endpoint does not support TZ, so won't support SetDSTOffset. - MTR_LOG_DEFAULT("%@ Unable to SetDSTOffset on endpoint %@, since it does not support the TZ feature", self, endpoint); + MTR_LOG("%@ Unable to SetDSTOffset on endpoint %@, since it does not support the TZ feature", self, endpoint); continue; } auto attrReport = [[MTRAttributeReport alloc] initWithResponseValue:@{ @@ -685,11 +685,17 @@ - (void)_setDSTOffsets:(NSArray #define MTR_DEVICE_SUBSCRIPTION_MAX_INTERVAL_MIN (10 * 60) // 10 minutes (for now) #define MTR_DEVICE_SUBSCRIPTION_MAX_INTERVAL_MAX (60 * 60) // 60 minutes +- (BOOL)_subscriptionsAllowed +{ + return ![_deviceController isKindOfClass:MTRDeviceControllerOverXPC.class]; +} + - (void)setDelegate:(id)delegate queue:(dispatch_queue_t)queue { - MTR_LOG_INFO("%@ setDelegate %@", self, delegate); + MTR_LOG("%@ setDelegate %@", self, delegate); - BOOL setUpSubscription = YES; + // We should not set up a subscription for device controllers over XPC. + BOOL setUpSubscription = [self _subscriptionsAllowed]; // For unit testing only #ifdef DEBUG @@ -724,7 +730,7 @@ - (void)setDelegate:(id)delegate queue:(dispatch_queue_t)queu - (void)invalidate { - MTR_LOG_INFO("%@ invalidate", self); + MTR_LOG("%@ invalidate", self); [_asyncWorkQueue invalidate]; @@ -755,7 +761,7 @@ - (void)nodeMayBeAdvertisingOperational { assertChipStackLockedByCurrentThread(); - MTR_LOG_DEFAULT("%@ saw new operational advertisement", self); + MTR_LOG("%@ saw new operational advertisement", self); [self _triggerResubscribeWithReason:"operational advertisement seen" nodeLikelyReachable:YES]; @@ -903,12 +909,12 @@ - (void)_changeState:(MTRDeviceState)state _state = state; if (lastState != state) { if (state != MTRDeviceStateReachable) { - MTR_LOG_INFO("%@ reachability state change %lu => %lu, set estimated start time to nil", self, static_cast(lastState), + MTR_LOG("%@ reachability state change %lu => %lu, set estimated start time to nil", self, static_cast(lastState), static_cast(state)); _estimatedStartTime = nil; _estimatedStartTimeFromGeneralDiagnosticsUpTime = nil; } else { - MTR_LOG_INFO( + MTR_LOG( "%@ reachability state change %lu => %lu", self, static_cast(lastState), static_cast(state)); } id delegate = _weakDelegate.strongObject; @@ -918,7 +924,7 @@ - (void)_changeState:(MTRDeviceState)state }); } } else { - MTR_LOG_INFO( + MTR_LOG( "%@ Not reporting reachability state change, since no change in state %lu => %lu", self, static_cast(lastState), static_cast(state)); } } @@ -929,10 +935,18 @@ - (void)_changeInternalState:(MTRInternalDeviceState)state MTRInternalDeviceState lastState = _internalDeviceState; _internalDeviceState = state; if (lastState != state) { - MTR_LOG_DEFAULT("%@ internal state change %lu => %lu", self, static_cast(lastState), static_cast(state)); + MTR_LOG("%@ internal state change %lu => %lu", self, static_cast(lastState), static_cast(state)); } } +#ifdef DEBUG +- (MTRInternalDeviceState)_getInternalState +{ + std::lock_guard lock(self->_lock); + return _internalDeviceState; +} +#endif + // First Time Sync happens 2 minutes after reachability (this can be changed in the future) #define MTR_DEVICE_TIME_UPDATE_INITIAL_WAIT_TIME_SEC (60 * 2) - (void)_handleSubscriptionEstablished @@ -1077,7 +1091,7 @@ - (void)_scheduleSubscriptionPoolWork:(dispatch_block_t)workBlock inNanoseconds: #endif if (self->_subscriptionPoolWorkCompletionBlock) { // This means a resubscription triggering event happened and is now in-progress - MTR_LOG_DEFAULT("%@ timer fired but already running in subscription pool - ignoring: %@", self, description); + MTR_LOG("%@ timer fired but already running in subscription pool - ignoring: %@", self, description); os_unfair_lock_unlock(&self->_lock); // call completion as complete to remove from queue @@ -1165,7 +1179,7 @@ - (void)_handleSubscriptionReset:(NSNumber * _Nullable)retryDelay // don't schedule multiple retries if (self.reattemptingSubscription) { - MTR_LOG_DEFAULT("%@ already reattempting subscription", self); + MTR_LOG("%@ already reattempting subscription", self); return; } @@ -1182,7 +1196,7 @@ - (void)_handleSubscriptionReset:(NSNumber * _Nullable)retryDelay // the device told us to use. _lastSubscriptionAttemptWait = 0; secondsToWait = retryDelay.doubleValue; - MTR_LOG_INFO("%@ resetting resubscribe attempt counter, and delaying by the server-provided delay: %f", + MTR_LOG("%@ resetting resubscribe attempt counter, and delaying by the server-provided delay: %f", self, secondsToWait); } else { _lastSubscriptionAttemptWait *= 2; @@ -1192,7 +1206,7 @@ - (void)_handleSubscriptionReset:(NSNumber * _Nullable)retryDelay secondsToWait = _lastSubscriptionAttemptWait; } - MTR_LOG_DEFAULT("%@ scheduling to reattempt subscription in %f seconds", self, secondsToWait); + MTR_LOG("%@ scheduling to reattempt subscription in %f seconds", self, secondsToWait); // If we started subscription or session establishment but failed, remove item from the subscription pool so we can re-queue. [self _clearSubscriptionPoolWork]; @@ -1222,7 +1236,7 @@ - (void)_reattemptSubscriptionNowIfNeeded return; } - MTR_LOG_DEFAULT("%@ reattempting subscription", self); + MTR_LOG("%@ reattempting subscription", self); self.reattemptingSubscription = NO; [self _setupSubscription]; } @@ -1258,7 +1272,7 @@ - (void)_markDeviceAsUnreachableIfNeverSubscribed return; } - MTR_LOG_DEFAULT("%@ still not subscribed, marking the device as unreachable", self); + MTR_LOG("%@ still not subscribed, marking the device as unreachable", self); [self _changeState:MTRDeviceStateUnreachable]; } @@ -1296,7 +1310,7 @@ - (void)_handleReportEnd BOOL dataStoreExists = _deviceController.controllerDataStore != nil; if (dataStoreExists && _clusterDataToPersist != nil && _clusterDataToPersist.count) { - MTR_LOG_DEFAULT("%@ Storing cluster information (data version and attributes) count: %lu", self, static_cast(_clusterDataToPersist.count)); + MTR_LOG("%@ Storing cluster information (data version and attributes) count: %lu", self, static_cast(_clusterDataToPersist.count)); // We're going to hand out these MTRDeviceClusterData objects to our // storage implementation, which will try to read them later. Make sure // we snapshot the state here instead of handing out live copies. @@ -1428,12 +1442,12 @@ - (void)_handleEventReport:(NSArray *> *)eventRepor if (isStartUpEvent) { if (_estimatedStartTimeFromGeneralDiagnosticsUpTime) { // If UpTime was received, make use of it as mark of system start time - MTR_LOG_INFO("%@ StartUp event: set estimated start time forward to %@", self, + MTR_LOG("%@ StartUp event: set estimated start time forward to %@", self, _estimatedStartTimeFromGeneralDiagnosticsUpTime); _estimatedStartTime = _estimatedStartTimeFromGeneralDiagnosticsUpTime; } else { // If UpTime was not received, reset estimated start time in case of reboot - MTR_LOG_INFO("%@ StartUp event: set estimated start time to nil", self); + MTR_LOG("%@ StartUp event: set estimated start time to nil", self); _estimatedStartTime = nil; } } @@ -1468,7 +1482,7 @@ - (void)_handleEventReport:(NSArray *> *)eventRepor [reportToReturn addObject:eventToReturn]; } if (oldEstimatedStartTime != _estimatedStartTime) { - MTR_LOG_DEFAULT("%@ updated estimated start time to %@", self, _estimatedStartTime); + MTR_LOG("%@ updated estimated start time to %@", self, _estimatedStartTime); } id delegate = _weakDelegate.strongObject; @@ -1680,6 +1694,11 @@ - (void)_setupSubscription { os_unfair_lock_assert_owner(&self->_lock); + if (![self _subscriptionsAllowed]) { + MTR_LOG("_setupSubscription: Subscriptions not allowed. Do not set up subscription"); + return; + } + #ifdef DEBUG id delegate = _weakDelegate.strongObject; Optional maxIntervalOverride; @@ -1724,7 +1743,7 @@ - (void)_setupSubscription auto callback = std::make_unique( ^(NSArray * value) { - MTR_LOG_INFO("%@ got attribute report %@", self, value); + MTR_LOG("%@ got attribute report %@", self, value); dispatch_async(self.queue, ^{ // OnAttributeData [self _handleAttributeReport:value fromSubscription:YES]; @@ -1734,7 +1753,7 @@ - (void)_setupSubscription }); }, ^(NSArray * value) { - MTR_LOG_INFO("%@ got event report %@", self, value); + MTR_LOG("%@ got event report %@", self, value); dispatch_async(self.queue, ^{ // OnEventReport [self _handleEventReport:value]; @@ -1755,14 +1774,14 @@ - (void)_setupSubscription }); }, ^(void) { - MTR_LOG_DEFAULT("%@ got subscription established", self); + MTR_LOG("%@ got subscription established", self); dispatch_async(self.queue, ^{ // OnSubscriptionEstablished [self _handleSubscriptionEstablished]; }); }, ^(void) { - MTR_LOG_DEFAULT("%@ got subscription done", self); + MTR_LOG("%@ got subscription done", self); // Drop our pointer to the ReadClient immediately, since // it's about to be destroyed and we don't want to be // holding a dangling pointer. @@ -1776,20 +1795,20 @@ - (void)_setupSubscription }); }, ^(void) { - MTR_LOG_DEFAULT("%@ got unsolicited message from publisher", self); + MTR_LOG("%@ got unsolicited message from publisher", self); dispatch_async(self.queue, ^{ // OnUnsolicitedMessageFromPublisher [self _handleUnsolicitedMessageFromPublisher]; }); }, ^(void) { - MTR_LOG_DEFAULT("%@ got report begin", self); + MTR_LOG("%@ got report begin", self); dispatch_async(self.queue, ^{ [self _handleReportBegin]; }); }, ^(void) { - MTR_LOG_DEFAULT("%@ got report end", self); + MTR_LOG("%@ got report end", self); dispatch_async(self.queue, ^{ [self _handleReportEnd]; }); @@ -1884,7 +1903,7 @@ - (void)_setupSubscription return; } - MTR_LOG_DEFAULT("%@ Subscribe with data version list size %lu, reduced by %lu", self, (unsigned long) dataVersions.count, (unsigned long) dataVersionFilterListSizeReduction); + MTR_LOG("%@ Subscribe with data version list size %lu, reduced by %lu", self, (unsigned long) dataVersions.count, (unsigned long) dataVersionFilterListSizeReduction); // Callback and ClusterStateCache and ReadClient will be deleted // when OnDone is called. @@ -2099,14 +2118,14 @@ static BOOL AttributeHasChangesOmittedQuality(MTRAttributePath * attributePath) while (readRequestsNext.count) { // Can only read up to 9 paths at a time, per spec if (readRequestsCurrent.count >= 9) { - MTR_LOG_INFO("Batching read attribute work item [%llu]: cannot add more work, item is full [0x%016llX:%@:0x%llx:0x%llx]", workItemID, nodeID.unsignedLongLongValue, endpointID, clusterID.unsignedLongLongValue, attributeID.unsignedLongLongValue); + MTR_LOG("Batching read attribute work item [%llu]: cannot add more work, item is full [0x%016llX:%@:0x%llx:0x%llx]", workItemID, nodeID.unsignedLongLongValue, endpointID, clusterID.unsignedLongLongValue, attributeID.unsignedLongLongValue); return outcome; } // if params don't match then they cannot be merged if (![readRequestsNext[0][MTRDeviceReadRequestFieldParamsIndex] isEqual:readRequestsCurrent[0][MTRDeviceReadRequestFieldParamsIndex]]) { - MTR_LOG_INFO("Batching read attribute work item [%llu]: cannot add more work, parameter mismatch [0x%016llX:%@:0x%llx:0x%llx]", workItemID, nodeID.unsignedLongLongValue, endpointID, clusterID.unsignedLongLongValue, attributeID.unsignedLongLongValue); + MTR_LOG("Batching read attribute work item [%llu]: cannot add more work, parameter mismatch [0x%016llX:%@:0x%llx:0x%llx]", workItemID, nodeID.unsignedLongLongValue, endpointID, clusterID.unsignedLongLongValue, attributeID.unsignedLongLongValue); return outcome; } @@ -2114,7 +2133,7 @@ static BOOL AttributeHasChangesOmittedQuality(MTRAttributePath * attributePath) auto readItem = readRequestsNext.firstObject; [readRequestsNext removeObjectAtIndex:0]; [readRequestsCurrent addObject:readItem]; - MTR_LOG_INFO("Batching read attribute work item [%llu]: added %@ (now %tu requests total) [0x%016llX:%@:0x%llx:0x%llx]", + MTR_LOG("Batching read attribute work item [%llu]: added %@ (now %tu requests total) [0x%016llX:%@:0x%llx:0x%llx]", workItemID, readItem, readRequestsCurrent.count, nodeID.unsignedLongLongValue, endpointID, clusterID.unsignedLongLongValue, attributeID.unsignedLongLongValue); outcome = MTRBatchedPartially; } @@ -2125,7 +2144,7 @@ static BOOL AttributeHasChangesOmittedQuality(MTRAttributePath * attributePath) mtr_hide(self); // don't capture self accidentally for (NSArray * readItem in readRequests) { if ([readItem isEqual:opaqueItemData]) { - MTR_LOG_DEFAULT("Read attribute work item [%llu] report duplicate %@ [0x%016llX:%@:0x%llx:0x%llx]", workItemID, readItem, nodeID.unsignedLongLongValue, endpointID, clusterID.unsignedLongLongValue, attributeID.unsignedLongLongValue); + MTR_LOG("Read attribute work item [%llu] report duplicate %@ [0x%016llX:%@:0x%llx:0x%llx]", workItemID, readItem, nodeID.unsignedLongLongValue, endpointID, clusterID.unsignedLongLongValue, attributeID.unsignedLongLongValue); *isDuplicate = YES; *stop = YES; return; @@ -2162,7 +2181,7 @@ static BOOL AttributeHasChangesOmittedQuality(MTRAttributePath * attributePath) if (values) { // Since the format is the same data-value dictionary, this looks like an // attribute report - MTR_LOG_INFO("Read attribute work item [%llu] result: %@ [0x%016llX:%@:0x%llX:0x%llX]", workItemID, values, nodeID.unsignedLongLongValue, endpointID, clusterID.unsignedLongLongValue, attributeID.unsignedLongLongValue); + MTR_LOG("Read attribute work item [%llu] result: %@ [0x%016llX:%@:0x%llX:0x%llX]", workItemID, values, nodeID.unsignedLongLongValue, endpointID, clusterID.unsignedLongLongValue, attributeID.unsignedLongLongValue); [self _handleAttributeReport:values fromSubscription:NO]; } @@ -2172,7 +2191,7 @@ static BOOL AttributeHasChangesOmittedQuality(MTRAttributePath * attributePath) completion(MTRAsyncWorkNeedsRetry); } else { if (error) { - MTR_LOG_DEFAULT("Read attribute work item [%llu] failed (giving up): %@ [0x%016llX:%@:0x%llx:0x%llx]", workItemID, error, nodeID.unsignedLongLongValue, endpointID, clusterID.unsignedLongLongValue, attributeID.unsignedLongLongValue); + MTR_LOG("Read attribute work item [%llu] failed (giving up): %@ [0x%016llX:%@:0x%llx:0x%llx]", workItemID, error, nodeID.unsignedLongLongValue, endpointID, clusterID.unsignedLongLongValue, attributeID.unsignedLongLongValue); } completion(MTRAsyncWorkComplete); } @@ -2252,7 +2271,7 @@ - (void)writeAttributeWithEndpointID:(NSNumber *)endpointID // with the later one. if (![writeRequestsNext[0][MTRDeviceWriteRequestFieldPathIndex] isEqual:writeRequestsCurrent[0][MTRDeviceWriteRequestFieldPathIndex]]) { - MTR_LOG_INFO("Batching write attribute work item [%llu]: cannot replace with next work item due to path mismatch", workItemID); + MTR_LOG("Batching write attribute work item [%llu]: cannot replace with next work item due to path mismatch", workItemID); return outcome; } @@ -2260,7 +2279,7 @@ - (void)writeAttributeWithEndpointID:(NSNumber *)endpointID auto writeItem = writeRequestsNext.firstObject; [writeRequestsNext removeObjectAtIndex:0]; [writeRequestsCurrent replaceObjectAtIndex:0 withObject:writeItem]; - MTR_LOG_INFO("Batching write attribute work item [%llu]: replaced with new write value %@ [0x%016llX]", + MTR_LOG("Batching write attribute work item [%llu]: replaced with new write value %@ [0x%016llX]", workItemID, writeItem, nodeID.unsignedLongLongValue); outcome = MTRBatchedPartially; } @@ -2444,7 +2463,7 @@ - (void)_invokeCommandWithEndpointID:(NSNumber *)endpointID completion:^(NSArray *> * _Nullable values, NSError * _Nullable error) { // Log the data at the INFO level (not usually persisted permanently), // but make sure we log the work completion at the DEFAULT level. - MTR_LOG_INFO("Invoke work item [%llu] received command response: %@ error: %@", workItemID, values, error); + MTR_LOG("Invoke work item [%llu] received command response: %@ error: %@", workItemID, values, error); // TODO: This 5-retry cap is very arbitrary. // TODO: Should there be some sort of backoff here? if (error != nil && error.domain == MTRInteractionErrorDomain && error.code == MTRInteractionErrorCodeBusy && retryCount < 5) { @@ -2591,7 +2610,7 @@ - (void)_checkExpiredExpectedValues } // log attribute paths - MTR_LOG_INFO("%@ report from expired expected values %@", self, attributePathsToReport); + MTR_LOG("%@ report from expired expected values %@", self, attributePathsToReport); [self _reportAttributes:attributesToReport]; // Have a reasonable minimum wait time for expiration timers @@ -2642,7 +2661,7 @@ - (void)_performScheduledExpirationCheck return cachedAttributeValue; } else { // TODO: when not found in cache, generated default values should be used - MTR_LOG_INFO("%@ _attributeValueDictionaryForAttributePath: could not find cached attribute values for attribute %@", self, + MTR_LOG("%@ _attributeValueDictionaryForAttributePath: could not find cached attribute values for attribute %@", self, attributePath); } @@ -2743,7 +2762,7 @@ - (NSArray *)_getAttributesToReportWithReportedValues:(NSArray %@", self, upTime, + MTR_LOG("%@ General Diagnostics UpTime %.3lf: estimated start time %@ => %@", self, upTime, oldSystemStartTime, potentialSystemStartTime); _estimatedStartTime = potentialSystemStartTime; } @@ -2854,7 +2873,7 @@ - (NSArray *)_getAttributesToReportWithReportedValues:(NSArray *)clusterData { - MTR_LOG_INFO("%@ setPersistedClusterData count: %lu", self, static_cast(clusterData.count)); + MTR_LOG("%@ setPersistedClusterData count: %lu", self, static_cast(clusterData.count)); if (!clusterData.count) { return; } @@ -3044,7 +3063,7 @@ - (NSArray *)_getAttributesToReportWithNewExpectedValues:(NSArray *> *)values // since NSTimeInterval is in seconds, convert ms into seconds in double NSDate * expirationTime = [NSDate dateWithTimeIntervalSinceNow:expectedValueInterval.doubleValue / 1000]; - MTR_LOG_INFO( + MTR_LOG( "%@ Setting expected values %@ with expiration time %f seconds from now", self, values, [expirationTime timeIntervalSinceNow]); std::lock_guard lock(_lock); @@ -3107,7 +3126,7 @@ - (void)_removeExpectedValueForAttributePath:(MTRAttributePath *)attributePath e expectedValueID:expectedValueID previousValue:&previousValue]; - MTR_LOG_INFO("%@ remove expected value for path %@ should report %@", self, attributePath, shouldReportValue ? @"YES" : @"NO"); + MTR_LOG("%@ remove expected value for path %@ should report %@", self, attributePath, shouldReportValue ? @"YES" : @"NO"); if (shouldReportValue) { NSMutableDictionary * attribute = [NSMutableDictionary dictionaryWithObject:attributePath forKey:MTRAttributePathKey]; diff --git a/src/darwin/Framework/CHIP/MTRDeviceAttestationDelegateBridge.mm b/src/darwin/Framework/CHIP/MTRDeviceAttestationDelegateBridge.mm index b044cb6502dceb..38e6ba08165fc0 100644 --- a/src/darwin/Framework/CHIP/MTRDeviceAttestationDelegateBridge.mm +++ b/src/darwin/Framework/CHIP/MTRDeviceAttestationDelegateBridge.mm @@ -28,7 +28,7 @@ chip::Credentials::AttestationVerificationResult attestationResult) { dispatch_async(mQueue, ^{ - MTR_LOG_DEFAULT("MTRDeviceAttestationDelegateBridge::OnDeviceAttestationFailed completed with result: %hu", + MTR_LOG("MTRDeviceAttestationDelegateBridge::OnDeviceAttestationFailed completed with result: %hu", chip::to_underlying(attestationResult)); mResult = attestationResult; diff --git a/src/darwin/Framework/CHIP/MTRDeviceConnectivityMonitor.mm b/src/darwin/Framework/CHIP/MTRDeviceConnectivityMonitor.mm index 80ad6f80d5be2b..3df270be9ce62e 100644 --- a/src/darwin/Framework/CHIP/MTRDeviceConnectivityMonitor.mm +++ b/src/darwin/Framework/CHIP/MTRDeviceConnectivityMonitor.mm @@ -154,7 +154,7 @@ - (void)handleResolvedHostname:(const char *)hostName port:(uint16_t)port error: if (self) { nw_path_status_t status = nw_path_get_status(path); if (status == nw_path_status_satisfied) { - MTR_LOG_INFO("%@ path is satisfied", self); + MTR_LOG("%@ path is satisfied", self); std::lock_guard lock(sConnectivityMonitorLock); [self _callHandler]; } @@ -165,7 +165,7 @@ - (void)handleResolvedHostname:(const char *)hostName port:(uint16_t)port error: if (self) { if (viable) { std::lock_guard lock(sConnectivityMonitorLock); - MTR_LOG_INFO("%@ connectivity now viable", self); + MTR_LOG("%@ connectivity now viable", self); [self _callHandler]; } } @@ -201,11 +201,11 @@ - (void)startMonitoringWithHandler:(MTRDeviceConnectivityMonitorHandler)handler // If there's already a resolver running, just return if (_resolvers.size() != 0) { - MTR_LOG_INFO("%@ connectivity monitor already running", self); + MTR_LOG("%@ connectivity monitor already running", self); return; } - MTR_LOG_INFO("%@ start connectivity monitoring for %@ (%lu monitoring objects)", self, _instanceName, static_cast(sConnectivityMonitorCount)); + MTR_LOG("%@ start connectivity monitoring for %@ (%lu monitoring objects)", self, _instanceName, static_cast(sConnectivityMonitorCount)); auto sharedConnection = [MTRDeviceConnectivityMonitor _sharedResolverConnection]; if (!sharedConnection) { @@ -259,7 +259,7 @@ - (void)_stopMonitoring std::lock_guard lock(sConnectivityMonitorLock); if (!sConnectivityMonitorCount) { - MTR_LOG_INFO("MTRDeviceConnectivityMonitor: Closing shared resolver connection"); + MTR_LOG("MTRDeviceConnectivityMonitor: Closing shared resolver connection"); DNSServiceRefDeallocate(sSharedResolverConnection); sSharedResolverConnection = NULL; sSharedResolverQueue = nil; @@ -273,7 +273,7 @@ - (void)stopMonitoring { // DNSServiceRefDeallocate must be called on the same queue set on the shared connection. dispatch_async(sSharedResolverQueue, ^{ - MTR_LOG_INFO("%@ stop connectivity monitoring for %@", self, self->_instanceName); + MTR_LOG("%@ stop connectivity monitoring for %@", self, self->_instanceName); std::lock_guard lock(sConnectivityMonitorLock); [self _stopMonitoring]; }); diff --git a/src/darwin/Framework/CHIP/MTRDeviceController.mm b/src/darwin/Framework/CHIP/MTRDeviceController.mm index 16b4d7f385e3aa..a66e4f186e1f02 100644 --- a/src/darwin/Framework/CHIP/MTRDeviceController.mm +++ b/src/darwin/Framework/CHIP/MTRDeviceController.mm @@ -264,11 +264,16 @@ - (instancetype)initWithFactory:(MTRDeviceControllerFactory *)factory } else { concurrentSubscriptionPoolSize = static_cast(subscriptionPoolSizeOverride); } + + MTR_LOG(" *** Overriding pool size of MTRDeviceController with: %tu", concurrentSubscriptionPoolSize); } if (!concurrentSubscriptionPoolSize) { concurrentSubscriptionPoolSize = 1; } + + MTR_LOG("Setting up pool size of MTRDeviceController with: %tu", concurrentSubscriptionPoolSize); + _concurrentSubscriptionPool = [[MTRAsyncWorkQueue alloc] initWithContext:self width:concurrentSubscriptionPoolSize]; _storedFabricIndex = chip::kUndefinedFabricIndex; @@ -595,13 +600,13 @@ - (BOOL)startup:(MTRDeviceControllerStartupParamsInternal *)startupParams if (_controllerDataStore) { // If the storage delegate supports the bulk read API, then a dictionary of nodeID => cluster data dictionary would be passed to the handler. Otherwise this would be a no-op, and stored attributes for MTRDevice objects will be loaded lazily in -deviceForNodeID:. [_controllerDataStore fetchAttributeDataForAllDevices:^(NSDictionary *> * _Nonnull clusterDataByNode) { - MTR_LOG_INFO("Loaded attribute values for %lu nodes from storage for controller uuid %@", static_cast(clusterDataByNode.count), self->_uniqueIdentifier); + MTR_LOG("Loaded attribute values for %lu nodes from storage for controller uuid %@", static_cast(clusterDataByNode.count), self->_uniqueIdentifier); std::lock_guard lock(self->_deviceMapLock); for (NSNumber * nodeID in clusterDataByNode) { NSDictionary * clusterData = clusterDataByNode[nodeID]; MTRDevice * device = [self _setupDeviceForNodeID:nodeID prefetchedClusterData:clusterData]; - MTR_LOG_INFO("Loaded %lu cluster data from storage for %@", static_cast(clusterData.count), device); + MTR_LOG("Loaded %lu cluster data from storage for %@", static_cast(clusterData.count), device); } }]; } @@ -631,7 +636,7 @@ - (BOOL)setupCommissioningSessionWithPayload:(MTRSetupPayload *)payload newNodeID:(NSNumber *)newNodeID error:(NSError * __autoreleasing *)error { - MTR_LOG_DEFAULT("Setting up commissioning session for device ID 0x%016llX with setup payload %@", newNodeID.unsignedLongLongValue, payload); + MTR_LOG("Setting up commissioning session for device ID 0x%016llX with setup payload %@", newNodeID.unsignedLongLongValue, payload); [[MTRMetricsCollector sharedInstance] resetMetrics]; @@ -684,7 +689,7 @@ - (BOOL)setupCommissioningSessionWithDiscoveredDevice:(MTRCommissionableBrowserR newNodeID:(NSNumber *)newNodeID error:(NSError * __autoreleasing *)error { - MTR_LOG_DEFAULT("Setting up commissioning session for already-discovered device %@ and device ID 0x%016llX with setup payload %@", discoveredDevice, newNodeID.unsignedLongLongValue, payload); + MTR_LOG("Setting up commissioning session for already-discovered device %@ and device ID 0x%016llX with setup payload %@", discoveredDevice, newNodeID.unsignedLongLongValue, payload); [[MTRMetricsCollector sharedInstance] resetMetrics]; @@ -942,7 +947,7 @@ - (MTRBaseDevice *)deviceBeingCommissionedWithNodeID:(NSNumber *)nodeID error:(N }; MTRBaseDevice * device = [self syncRunOnWorkQueueWithReturnValue:block error:error]; - MTR_LOG_DEFAULT("Getting device being commissioned with node ID 0x%016llX: %@ (error: %@)", + MTR_LOG("Getting device being commissioned with node ID 0x%016llX: %@ (error: %@)", nodeID.unsignedLongLongValue, device, (error ? *error : nil)); return device; } @@ -973,7 +978,7 @@ - (MTRDevice *)_setupDeviceForNodeID:(NSNumber *)nodeID prefetchedClusterData:(N } else if (_controllerDataStore) { // Load persisted cluster data if they exist. NSDictionary * clusterData = [_controllerDataStore getStoredClusterDataForNodeID:nodeID]; - MTR_LOG_INFO("Loaded %lu cluster data from storage for %@", static_cast(clusterData.count), deviceToReturn); + MTR_LOG("Loaded %lu cluster data from storage for %@", static_cast(clusterData.count), deviceToReturn); if (clusterData.count) { [deviceToReturn setPersistedClusterData:clusterData]; } @@ -1126,7 +1131,7 @@ - (BOOL)addServerEndpoint:(MTRServerEndpoint *)endpoint [self asyncDispatchToMatterQueue:^() { [self->_serverEndpoints addObject:endpoint]; [endpoint registerMatterEndpoint]; - MTR_LOG_DEFAULT("Added server endpoint %u to controller %@", static_cast(endpoint.endpointID.unsignedLongLongValue), + MTR_LOG("Added server endpoint %u to controller %@", static_cast(endpoint.endpointID.unsignedLongLongValue), self->_uniqueIdentifier); } errorHandler:^(NSError * error) { @@ -1154,7 +1159,7 @@ - (void)removeServerEndpointInternal:(MTRServerEndpoint *)endpoint queue:(dispat // tearing it down. [self asyncDispatchToMatterQueue:^() { [self removeServerEndpointOnMatterQueue:endpoint]; - MTR_LOG_DEFAULT("Removed server endpoint %u from controller %@", static_cast(endpoint.endpointID.unsignedLongLongValue), + MTR_LOG("Removed server endpoint %u from controller %@", static_cast(endpoint.endpointID.unsignedLongLongValue), self->_uniqueIdentifier); if (queue != nil && completion != nil) { dispatch_async(queue, completion); @@ -1162,7 +1167,7 @@ - (void)removeServerEndpointInternal:(MTRServerEndpoint *)endpoint queue:(dispat } errorHandler:^(NSError * error) { // Error means we got shut down, so the endpoint is removed now. - MTR_LOG_DEFAULT("controller %@ already shut down, so endpoint %u has already been removed", self->_uniqueIdentifier, + MTR_LOG("controller %@ already shut down, so endpoint %u has already been removed", self->_uniqueIdentifier, static_cast(endpoint.endpointID.unsignedLongLongValue)); if (queue != nil && completion != nil) { dispatch_async(queue, completion); diff --git a/src/darwin/Framework/CHIP/MTRDeviceControllerDataStore.mm b/src/darwin/Framework/CHIP/MTRDeviceControllerDataStore.mm index d2a3cf4ca73693..c96de65d39eb84 100644 --- a/src/darwin/Framework/CHIP/MTRDeviceControllerDataStore.mm +++ b/src/darwin/Framework/CHIP/MTRDeviceControllerDataStore.mm @@ -675,7 +675,7 @@ - (void)_clearStoredClusterDataForNodeID:(NSNumber *)nodeID MTR_LOG_ERROR("Delete failed for endpointIndex @ node 0x%016llX", nodeID.unsignedLongLongValue); } - MTR_LOG_INFO("clearStoredClusterDataForNodeID: deleted endpoints %lu/%lu clusters %lu/%lu", static_cast(endpointsCleared), static_cast(endpointsClearAttempts), static_cast(clusterDataCleared), static_cast(clusterDataClearAttempts)); + MTR_LOG("clearStoredClusterDataForNodeID: deleted endpoints %lu/%lu clusters %lu/%lu", static_cast(endpointsCleared), static_cast(endpointsClearAttempts), static_cast(clusterDataCleared), static_cast(clusterDataClearAttempts)); } - (void)clearStoredClusterDataForNodeID:(NSNumber *)nodeID @@ -729,7 +729,7 @@ - (void)clearAllStoredClusterData NSArray * nodeIndex = [self _fetchNodeIndex]; #if ATTRIBUTE_CACHE_VERBOSE_LOGGING - MTR_LOG_INFO("Fetch got %lu values for nodeIndex", static_cast(nodeIndex.count)); + MTR_LOG("Fetch got %lu values for nodeIndex", static_cast(nodeIndex.count)); #endif if (![nodeIndex containsObject:nodeID]) { @@ -743,7 +743,7 @@ - (void)clearAllStoredClusterData [self _clearStoredClusterDataForNodeID:nodeID]; } - MTR_LOG_INFO("Fetch got no value for endpointIndex @ node 0x%016llX", nodeID.unsignedLongLongValue); + MTR_LOG("Fetch got no value for endpointIndex @ node 0x%016llX", nodeID.unsignedLongLongValue); clusterDataToReturn = nil; return; } @@ -752,7 +752,7 @@ - (void)clearAllStoredClusterData NSArray * endpointIndex = [self _fetchEndpointIndexForNodeID:nodeID]; #if ATTRIBUTE_CACHE_VERBOSE_LOGGING - MTR_LOG_INFO("Fetch got %lu values for endpointIndex @ node 0x%016llX", static_cast(endpointIndex.count), nodeID.unsignedLongLongValue); + MTR_LOG("Fetch got %lu values for endpointIndex @ node 0x%016llX", static_cast(endpointIndex.count), nodeID.unsignedLongLongValue); #endif for (NSNumber * endpointID in endpointIndex) { @@ -760,19 +760,19 @@ - (void)clearAllStoredClusterData NSArray * clusterIndex = [self _fetchClusterIndexForNodeID:nodeID endpointID:endpointID]; #if ATTRIBUTE_CACHE_VERBOSE_LOGGING - MTR_LOG_INFO("Fetch got %lu values for clusterIndex @ node 0x%016llX %u", static_cast(clusterIndex.count), nodeID.unsignedLongLongValue, endpointID.unsignedShortValue); + MTR_LOG("Fetch got %lu values for clusterIndex @ node 0x%016llX %u", static_cast(clusterIndex.count), nodeID.unsignedLongLongValue, endpointID.unsignedShortValue); #endif for (NSNumber * clusterID in clusterIndex) { // Fetch cluster data MTRDeviceClusterData * clusterData = [self _fetchClusterDataForNodeID:nodeID endpointID:endpointID clusterID:clusterID]; if (!clusterData) { - MTR_LOG_INFO("Fetch got no value for clusterData @ node 0x%016llX endpoint %u cluster 0x%08lX", nodeID.unsignedLongLongValue, endpointID.unsignedShortValue, clusterID.unsignedLongValue); + MTR_LOG("Fetch got no value for clusterData @ node 0x%016llX endpoint %u cluster 0x%08lX", nodeID.unsignedLongLongValue, endpointID.unsignedShortValue, clusterID.unsignedLongValue); continue; } #if ATTRIBUTE_CACHE_VERBOSE_LOGGING - MTR_LOG_INFO("Fetch got clusterData @ node 0x%016llX endpoint %u cluster 0x%08lX", nodeID.unsignedLongLongValue, endpointID.unsignedShortValue, clusterID.unsignedLongValue); + MTR_LOG("Fetch got clusterData @ node 0x%016llX endpoint %u cluster 0x%08lX", nodeID.unsignedLongLongValue, endpointID.unsignedShortValue, clusterID.unsignedLongValue); #endif MTRClusterPath * path = [MTRClusterPath clusterPathWithEndpointID:endpointID clusterID:clusterID]; @@ -896,7 +896,7 @@ - (void)storeClusterData:(NSDictionary for (MTRClusterPath * path in clusterData) { MTRDeviceClusterData * data = clusterData[path]; #if ATTRIBUTE_CACHE_VERBOSE_LOGGING - MTR_LOG_INFO("Attempt to store clusterData @ node 0x%016llX endpoint %u cluster 0x%08lX", nodeID.unsignedLongLongValue, path.endpoint.unsignedShortValue, path.cluster.unsignedLongValue); + MTR_LOG("Attempt to store clusterData @ node 0x%016llX endpoint %u cluster 0x%08lX", nodeID.unsignedLongLongValue, path.endpoint.unsignedShortValue, path.cluster.unsignedLongValue); #endif if (bulkValuesToStore) { diff --git a/src/darwin/Framework/CHIP/MTRDeviceControllerDelegateBridge.mm b/src/darwin/Framework/CHIP/MTRDeviceControllerDelegateBridge.mm index 4c50f7fd2a7fa4..5972b17de804e2 100644 --- a/src/darwin/Framework/CHIP/MTRDeviceControllerDelegateBridge.mm +++ b/src/darwin/Framework/CHIP/MTRDeviceControllerDelegateBridge.mm @@ -62,7 +62,7 @@ void MTRDeviceControllerDelegateBridge::OnStatusUpdate(chip::Controller::DevicePairingDelegate::Status status) { - MTR_LOG_DEFAULT("DeviceControllerDelegate status updated: %d", status); + MTR_LOG("DeviceControllerDelegate status updated: %d", status); // If pairing failed, PASE failed. However, since OnPairingComplete(failure_code) might not be invoked in all cases, mark // end of PASE with timeout as assumed failure. If OnPairingComplete is invoked, the right error code will be updated in @@ -94,7 +94,7 @@ void MTRDeviceControllerDelegateBridge::OnPairingComplete(CHIP_ERROR error) { if (error == CHIP_NO_ERROR) { - MTR_LOG_DEFAULT("MTRDeviceControllerDelegate PASE session establishment succeeded."); + MTR_LOG("MTRDeviceControllerDelegate PASE session establishment succeeded."); } else { MTR_LOG_ERROR("MTRDeviceControllerDelegate PASE session establishment failed: %" CHIP_ERROR_FORMAT, error.Format()); } @@ -114,7 +114,7 @@ void MTRDeviceControllerDelegateBridge::OnPairingDeleted(CHIP_ERROR error) { - MTR_LOG_DEFAULT("DeviceControllerDelegate Pairing deleted. Status %s", chip::ErrorStr(error)); + MTR_LOG("DeviceControllerDelegate Pairing deleted. Status %s", chip::ErrorStr(error)); // This is never actually called; just do nothing. } @@ -124,7 +124,7 @@ chip::VendorId vendorId = info.basic.vendorId; uint16_t productId = info.basic.productId; - MTR_LOG_DEFAULT("DeviceControllerDelegate Read Commissioning Info. VendorId %u ProductId %u", vendorId, productId); + MTR_LOG("DeviceControllerDelegate Read Commissioning Info. VendorId %u ProductId %u", vendorId, productId); id strongDelegate = mDelegate; MTRDeviceController * strongController = mController; @@ -140,7 +140,7 @@ void MTRDeviceControllerDelegateBridge::OnCommissioningComplete(chip::NodeId nodeId, CHIP_ERROR error) { - MTR_LOG_DEFAULT("DeviceControllerDelegate Commissioning complete. NodeId %llu Status %s", nodeId, chip::ErrorStr(error)); + MTR_LOG("DeviceControllerDelegate Commissioning complete. NodeId %llu Status %s", nodeId, chip::ErrorStr(error)); MATTER_LOG_METRIC_END(kMetricDeviceCommissioning, error); id strongDelegate = mDelegate; @@ -149,7 +149,7 @@ // Always collect the metrics to avoid unbounded growth of the stats in the collector MTRMetrics * metrics = [[MTRMetricsCollector sharedInstance] metricSnapshot:TRUE]; - MTR_LOG_INFO("Device commissioning complete with metrics %@", metrics); + MTR_LOG("Device commissioning complete with metrics %@", metrics); if ([strongDelegate respondsToSelector:@selector(controller:commissioningComplete:nodeID:)] || [strongDelegate respondsToSelector:@selector(controller:commissioningComplete:nodeID:metrics:)]) { diff --git a/src/darwin/Framework/CHIP/MTRDeviceControllerFactory.mm b/src/darwin/Framework/CHIP/MTRDeviceControllerFactory.mm index ebedc0a8d6d1a3..53bf36e8a6e70c 100644 --- a/src/darwin/Framework/CHIP/MTRDeviceControllerFactory.mm +++ b/src/darwin/Framework/CHIP/MTRDeviceControllerFactory.mm @@ -72,7 +72,7 @@ static bool sExitHandlerRegistered = false; static void ShutdownOnExit() { - MTR_LOG_INFO("ShutdownOnExit invoked on exit"); + MTR_LOG("ShutdownOnExit invoked on exit"); [[MTRDeviceControllerFactory sharedInstance] stopControllerFactory]; } @@ -239,7 +239,7 @@ - (void)_assertCurrentQueueIsNotMatterQueue - (void)cleanupStartupObjects { assertChipStackLockedByCurrentThread(); - MTR_LOG_INFO("Cleaning startup objects in controller factory"); + MTR_LOG("Cleaning startup objects in controller factory"); // Make sure the deinit order here is the reverse of the init order in // startControllerFactory: @@ -441,7 +441,7 @@ - (void)stopControllerFactory dispatch_sync(_chipWorkQueue, ^{ VerifyOrReturn(_running); - MTR_LOG_INFO("Shutting down the Matter controller factory"); + MTR_LOG("Shutting down the Matter controller factory"); _controllerFactory->Shutdown(); [self cleanupStartupObjects]; _running = NO; @@ -498,7 +498,7 @@ - (MTRDeviceController * _Nullable)_startDeviceController:(MTRDeviceController * if (!_running) { // Note: reading _running from outside of the Matter work queue if (storageDelegate != nil) { - MTR_LOG_DEFAULT("Auto-starting Matter controller factory in per-controller storage mode"); + MTR_LOG("Auto-starting Matter controller factory in per-controller storage mode"); auto * params = [[MTRDeviceControllerFactoryParams alloc] initWithoutStorage]; if (![self _startControllerFactory:params startingController:YES error:error]) { return nil; @@ -766,7 +766,7 @@ - (void)preWarmCommissioningSession if (!self->_running) { MTR_LOG_ERROR("Can't pre-warm, Matter controller factory is not running"); } else { - MTR_LOG_DEFAULT("Pre-warming commissioning session"); + MTR_LOG("Pre-warming commissioning session"); self->_controllerFactory->EnsureAndRetainSystemState(); err = DeviceLayer::PlatformMgrImpl().StartBleScan(&self->_preWarmingDelegate, DeviceLayer::BleScanMode::kPreWarm); if (err != CHIP_NO_ERROR) { @@ -781,7 +781,7 @@ - (void)preWarmCommissioningSession - (void)preWarmCommissioningSessionDone { assertChipStackLockedByCurrentThread(); - MTR_LOG_DEFAULT("Pre-warming done"); + MTR_LOG("Pre-warming done"); self->_controllerFactory->ReleaseSystemState(); } diff --git a/src/darwin/Framework/CHIP/MTRDeviceControllerLocalTestStorage.mm b/src/darwin/Framework/CHIP/MTRDeviceControllerLocalTestStorage.mm index f51dae7bbbcaff..e1d039fd58053b 100644 --- a/src/darwin/Framework/CHIP/MTRDeviceControllerLocalTestStorage.mm +++ b/src/darwin/Framework/CHIP/MTRDeviceControllerLocalTestStorage.mm @@ -35,7 +35,7 @@ + (void)setLocalTestStorageEnabled:(BOOL)localTestStorageEnabled { NSUserDefaults * defaults = [[NSUserDefaults alloc] initWithSuiteName:kLocalTestUserDefaultDomain]; [defaults setBool:localTestStorageEnabled forKey:kLocalTestUserDefaultEnabledKey]; - MTR_LOG_INFO("MTRDeviceControllerLocalTestStorage setLocalTestStorageEnabled %d", localTestStorageEnabled); + MTR_LOG("MTRDeviceControllerLocalTestStorage setLocalTestStorageEnabled %d", localTestStorageEnabled); BOOL storedLocalTestStorageEnabled = [defaults boolForKey:kLocalTestUserDefaultEnabledKey]; if (storedLocalTestStorageEnabled != localTestStorageEnabled) { MTR_LOG_ERROR("MTRDeviceControllerLocalTestStorage setLocalTestStorageEnabled %d failed", localTestStorageEnabled); @@ -47,7 +47,7 @@ - (instancetype)initWithPassThroughStorage:(id UINT16_MAX) { - MTR_LOG_INFO("Warning: timeout is too large. It will be truncated to UINT16_MAX."); + MTR_LOG("Warning: timeout is too large. It will be truncated to UINT16_MAX."); timeoutInSeconds = UINT16_MAX; } else { timeoutInSeconds = static_cast(timeout); @@ -448,7 +448,7 @@ - (void)handleBDXTransferSessionBeginForFileDesignator:(NSString *)fileDesignato abortHandler:(AbortHandler)abortHandler; { assertChipStackLockedByCurrentThread(); - MTR_LOG_DEFAULT("BDX Transfer Session Begin: %@", fileDesignator); + MTR_LOG("BDX Transfer Session Begin: %@", fileDesignator); auto * download = [_downloads get:fileDesignator fabricIndex:fabricIndex nodeID:nodeID]; VerifyOrReturn(nil != download, completion([MTRError errorForCHIPErrorCode:CHIP_ERROR_NOT_FOUND])); @@ -464,7 +464,7 @@ - (void)handleBDXTransferSessionDataForFileDesignator:(NSString *)fileDesignator completion:(MTRStatusCompletion)completion { assertChipStackLockedByCurrentThread(); - MTR_LOG_DEFAULT("BDX Transfer Session Data: %@: %@", fileDesignator, data); + MTR_LOG("BDX Transfer Session Data: %@: %@", fileDesignator, data); auto * download = [_downloads get:fileDesignator fabricIndex:fabricIndex nodeID:nodeID]; VerifyOrReturn(nil != download, completion([MTRError errorForCHIPErrorCode:CHIP_ERROR_NOT_FOUND])); @@ -482,7 +482,7 @@ - (void)handleBDXTransferSessionEndForFileDesignator:(NSString *)fileDesignator error:(NSError * _Nullable)error { assertChipStackLockedByCurrentThread(); - MTR_LOG_DEFAULT("BDX Transfer Session End: %@: %@", fileDesignator, error); + MTR_LOG("BDX Transfer Session End: %@: %@", fileDesignator, error); auto * download = [_downloads get:fileDesignator fabricIndex:fabricIndex nodeID:nodeID]; VerifyOrReturn(nil != download); diff --git a/src/darwin/Framework/CHIP/MTRLogging_Internal.h b/src/darwin/Framework/CHIP/MTRLogging_Internal.h index 27ee9b9dda301e..99892acf9631df 100644 --- a/src/darwin/Framework/CHIP/MTRLogging_Internal.h +++ b/src/darwin/Framework/CHIP/MTRLogging_Internal.h @@ -20,7 +20,6 @@ #include +#define MTR_LOG(msg, ...) ChipLogProgress(NotSpecified, msg, ##__VA_ARGS__) #define MTR_LOG_ERROR(msg, ...) ChipLogError(NotSpecified, msg, ##__VA_ARGS__) -#define MTR_LOG_DEFAULT(msg, ...) ChipLogProgress(NotSpecified, msg, ##__VA_ARGS__) -#define MTR_LOG_INFO(msg, ...) ChipLogProgress(NotSpecified, msg, ##__VA_ARGS__) #define MTR_LOG_DEBUG(msg, ...) ChipLogDetail(NotSpecified, msg, ##__VA_ARGS__) // same as INFO diff --git a/src/darwin/Framework/CHIP/MTRMetricsCollector.mm b/src/darwin/Framework/CHIP/MTRMetricsCollector.mm index 0927da858f1298..92a9ab4b6d373c 100644 --- a/src/darwin/Framework/CHIP/MTRMetricsCollector.mm +++ b/src/darwin/Framework/CHIP/MTRMetricsCollector.mm @@ -113,7 +113,7 @@ - (void)unregisterTracingBackend; void StartupMetricsCollection() { if ([MTRMetricsCollector sharedInstance]) { - MTR_LOG_INFO("Initialized metrics collection backend for Darwin"); + MTR_LOG("Initialized metrics collection backend for Darwin"); [[MTRMetricsCollector sharedInstance] registerTracingBackend]; } @@ -167,7 +167,7 @@ - (void)registerTracingBackend // Register only once if (!_tracingBackendRegistered) { chip::Tracing::Register(_tracingBackend); - MTR_LOG_INFO("Registered tracing backend with the registry"); + MTR_LOG("Registered tracing backend with the registry"); _tracingBackendRegistered = TRUE; } } @@ -179,7 +179,7 @@ - (void)unregisterTracingBackend // Unregister only if registered before if (_tracingBackendRegistered) { chip::Tracing::Unregister(_tracingBackend); - MTR_LOG_INFO("Unregistered tracing backend with the registry"); + MTR_LOG("Unregistered tracing backend with the registry"); _tracingBackendRegistered = FALSE; } } diff --git a/src/darwin/Framework/CHIP/ServerEndpoint/MTRServerAttribute.mm b/src/darwin/Framework/CHIP/ServerEndpoint/MTRServerAttribute.mm index d4bf1c7b9cd595..619ca98b2f4b47 100644 --- a/src/darwin/Framework/CHIP/ServerEndpoint/MTRServerAttribute.mm +++ b/src/darwin/Framework/CHIP/ServerEndpoint/MTRServerAttribute.mm @@ -136,14 +136,14 @@ - (BOOL)setValueInternal:(NSDictionary *)value logIfNotAssociate _value = [value copy]; - MTR_LOG_DEFAULT("Attribute value updated: %@", [self _descriptionWhileLocked]); // Logs new value as part of our description. + MTR_LOG("Attribute value updated: %@", [self _descriptionWhileLocked]); // Logs new value as part of our description. MTRDeviceController * deviceController = _deviceController; if (deviceController == nil) { // We're not bound to a controller, so safe to directly update // _serializedValue. if (logIfNotAssociated) { - MTR_LOG_DEFAULT("Not publishing value for attribute " ChipLogFormatMEI "; not bound to a controller", + MTR_LOG("Not publishing value for attribute " ChipLogFormatMEI "; not bound to a controller", ChipLogValueMEI(static_cast(_attributeID.unsignedLongLongValue))); } _serializedValue = serializedValue; @@ -181,7 +181,7 @@ - (BOOL)associateWithController:(nullable MTRDeviceController *)controller _deviceController = controller; - MTR_LOG_DEFAULT("Associated %@ with controller", [self _descriptionWhileLocked]); + MTR_LOG("Associated %@ with controller", [self _descriptionWhileLocked]); return YES; } diff --git a/src/darwin/Framework/CHIP/ServerEndpoint/MTRServerCluster.mm b/src/darwin/Framework/CHIP/ServerEndpoint/MTRServerCluster.mm index 02b5605e8c3388..e00bd10b5dc6c7 100644 --- a/src/darwin/Framework/CHIP/ServerEndpoint/MTRServerCluster.mm +++ b/src/darwin/Framework/CHIP/ServerEndpoint/MTRServerCluster.mm @@ -346,7 +346,7 @@ - (BOOL)associateWithController:(nullable MTRDeviceController *)controller _deviceController = controller; - MTR_LOG_DEFAULT("Associated %@, attribute count %llu, with controller", [self _descriptionWhileLocked], + MTR_LOG("Associated %@, attribute count %llu, with controller", [self _descriptionWhileLocked], static_cast(attributeCount)); return YES; diff --git a/src/darwin/Framework/CHIP/ServerEndpoint/MTRServerEndpoint.mm b/src/darwin/Framework/CHIP/ServerEndpoint/MTRServerEndpoint.mm index 44da6a6cb6016a..d9e54bce58d395 100644 --- a/src/darwin/Framework/CHIP/ServerEndpoint/MTRServerEndpoint.mm +++ b/src/darwin/Framework/CHIP/ServerEndpoint/MTRServerEndpoint.mm @@ -311,7 +311,7 @@ - (BOOL)finishAssociationWithController:(nullable MTRDeviceController *)controll _deviceController = controller; - MTR_LOG_DEFAULT("Associated %@, cluster count %llu, with controller", + MTR_LOG("Associated %@, cluster count %llu, with controller", self, static_cast(clusterCount)); return YES; diff --git a/src/darwin/Framework/CHIPTests/MTRDeviceTests.m b/src/darwin/Framework/CHIPTests/MTRDeviceTests.m index 1c2d5ddfe39a9a..26152705613790 100644 --- a/src/darwin/Framework/CHIPTests/MTRDeviceTests.m +++ b/src/darwin/Framework/CHIPTests/MTRDeviceTests.m @@ -3618,6 +3618,36 @@ - (void)test034_TestMTRDeviceHistoricalEvents XCTAssertTrue(eventReportsReceived > 0); } +- (void)test035_TestMTRDeviceSubscriptionNotEstablishedOverXPC +{ + NSString * const MTRDeviceControllerId = @"MTRController"; + __auto_type remoteController = [MTRDeviceController + sharedControllerWithID:MTRDeviceControllerId + xpcConnectBlock:^NSXPCConnection * _Nonnull { + return nil; + }]; + + __auto_type * device = [MTRDevice deviceWithNodeID:kDeviceId deviceController:remoteController]; + dispatch_queue_t queue = dispatch_get_main_queue(); + + // We should not set up a subscription when creating a MTRDevice with a remote controller. + XCTestExpectation * subscriptionExpectation = [self expectationWithDescription:@"Subscription has been set up"]; + subscriptionExpectation.inverted = YES; + + __auto_type * delegate = [[MTRDeviceTestDelegate alloc] init]; + + XCTAssertTrue([device _getInternalState] == MTRInternalDeviceStateUnsubscribed); + + delegate.onAttributeDataReceived = ^(NSArray *> * attributeReport) { + [subscriptionExpectation fulfill]; + }; + + [device setDelegate:delegate queue:queue]; + [self waitForExpectations:@[ subscriptionExpectation ] timeout:30]; + + XCTAssertTrue([device _getInternalState] == MTRInternalDeviceStateUnsubscribed); +} + @end @interface MTRDeviceEncoderTests : XCTestCase diff --git a/src/darwin/Framework/CHIPTests/TestHelpers/MTRTestDeclarations.h b/src/darwin/Framework/CHIPTests/TestHelpers/MTRTestDeclarations.h index 0cf5707c05c8b4..3c27a1fcc0102e 100644 --- a/src/darwin/Framework/CHIPTests/TestHelpers/MTRTestDeclarations.h +++ b/src/darwin/Framework/CHIPTests/TestHelpers/MTRTestDeclarations.h @@ -59,10 +59,31 @@ NS_ASSUME_NONNULL_BEGIN @end @interface MTRDevice (TestDebug) +typedef NS_ENUM(NSUInteger, MTRInternalDeviceState) { + // Unsubscribed means we do not have a subscription and are not trying to set one up. + MTRInternalDeviceStateUnsubscribed = 0, + // Subscribing means we are actively trying to establish our initial subscription (e.g. doing + // DNS-SD discovery, trying to establish CASE to the peer, getting priming reports, etc). + MTRInternalDeviceStateSubscribing = 1, + // InitialSubscriptionEstablished means we have at some point finished setting up a + // subscription. That subscription may have dropped since then, but if so it's the ReadClient's + // responsibility to re-establish it. + MTRInternalDeviceStateInitialSubscriptionEstablished = 2, + // Resubscribing means we had established a subscription, but then + // detected a subscription drop due to not receiving a report on time. This + // covers all the actions that happen when re-subscribing (discovery, CASE, + // getting priming reports, etc). + MTRInternalDeviceStateResubscribing = 3, + // LaterSubscriptionEstablished meant that we had a subscription drop and + // then re-created a subscription. + MTRInternalDeviceStateLaterSubscriptionEstablished = 4, +}; + - (void)unitTestInjectEventReport:(NSArray *> *)eventReport; - (void)unitTestInjectAttributeReport:(NSArray *> *)attributeReport fromSubscription:(BOOL)isFromSubscription; - (NSUInteger)unitTestAttributesReportedSinceLastCheck; - (void)unitTestClearClusterData; +- (MTRInternalDeviceState)_getInternalState; @end #endif