From 06e08a149636e278adc23af97e37ad9f50b22005 Mon Sep 17 00:00:00 2001 From: Justin Wood Date: Mon, 8 Jul 2024 13:06:04 -1000 Subject: [PATCH 1/3] Adding logging so we can debug stuff... --- .../commands/common/CHIPCommandBridge.h | 2 +- .../commands/pairing/DeviceControllerDelegateBridge.mm | 2 +- src/darwin/Framework/CHIP/MTRDevice.mm | 10 +++++++--- src/darwin/Framework/CHIP/MTRError_Internal.h | 4 ++++ 4 files changed, 13 insertions(+), 5 deletions(-) diff --git a/examples/darwin-framework-tool/commands/common/CHIPCommandBridge.h b/examples/darwin-framework-tool/commands/common/CHIPCommandBridge.h index 7dc5b848e22324..6cb580ded9c35f 100644 --- a/examples/darwin-framework-tool/commands/common/CHIPCommandBridge.h +++ b/examples/darwin-framework-tool/commands/common/CHIPCommandBridge.h @@ -39,7 +39,7 @@ class CHIPCommandBridge : public Command { { AddArgument("commissioner-name", &mCommissionerName); AddArgument("commissioner-nodeId", 0, UINT64_MAX, &mCommissionerNodeId, - "Sets the commisser node ID of the given " + "Sets the commissioner node ID of the given " "commissioner-name. Interactive mode will only set a single commissioner on the inital command. " "The commissioner node ID will be persisted until a different one is specified."); AddArgument("paa-trust-store-path", &mPaaTrustStorePath, diff --git a/examples/darwin-framework-tool/commands/pairing/DeviceControllerDelegateBridge.mm b/examples/darwin-framework-tool/commands/pairing/DeviceControllerDelegateBridge.mm index 9723199ed007a4..52f0fd4bb10a17 100644 --- a/examples/darwin-framework-tool/commands/pairing/DeviceControllerDelegateBridge.mm +++ b/examples/darwin-framework-tool/commands/pairing/DeviceControllerDelegateBridge.mm @@ -36,7 +36,7 @@ - (void)controller:(MTRDeviceController *)controller statusUpdate:(MTRCommission ChipLogError(chipTool, "MTRCommissioningStatusDiscoveringMoreDevices: This should not happen."); break; case MTRCommissioningStatusUnknown: - ChipLogError(chipTool, "Uknown Pairing Status"); + ChipLogError(chipTool, "Unknown Pairing Status"); break; } } diff --git a/src/darwin/Framework/CHIP/MTRDevice.mm b/src/darwin/Framework/CHIP/MTRDevice.mm index 30d96d3c2e9f43..2d4abce3cfd3cd 100644 --- a/src/darwin/Framework/CHIP/MTRDevice.mm +++ b/src/darwin/Framework/CHIP/MTRDevice.mm @@ -177,8 +177,8 @@ - (void)_deviceInternalStateChanged:(MTRDevice *)device; UnsolicitedMessageFromPublisherHandler unsolicitedMessageFromPublisherHandler, ReportBeginHandler reportBeginHandler, ReportEndHandler reportEndHandler) : MTRBaseSubscriptionCallback(attributeReportCallback, eventReportCallback, errorCallback, resubscriptionCallback, - subscriptionEstablishedHandler, onDoneHandler, unsolicitedMessageFromPublisherHandler, reportBeginHandler, - reportEndHandler) + subscriptionEstablishedHandler, onDoneHandler, unsolicitedMessageFromPublisherHandler, reportBeginHandler, + reportEndHandler) { } @@ -844,11 +844,13 @@ - (void)_addDelegate:(id)delegate queue:(dispatch_queue_t)que #endif if (shouldSetUpSubscription) { + MTR_LOG("%@ - starting subscription setup", self); // Record the time of first addDelegate call that triggers initial subscribe, and do not reset this value on subsequent addDelegate calls if (!_initialSubscribeStart) { _initialSubscribeStart = [NSDate now]; } if ([self _deviceUsesThread]) { + MTR_LOG(" => %@ - device is a thread device, scheduling in pool"); [self _scheduleSubscriptionPoolWork:^{ std::lock_guard lock(self->_lock); [self _setupSubscriptionWithReason:@"delegate is set and scheduled subscription is happening"]; @@ -1301,7 +1303,7 @@ - (void)_scheduleSubscriptionPoolWork:(dispatch_block_t)workBlock inNanoseconds: // Sanity check we are not scheduling for this device multiple times in the pool if (_subscriptionPoolWorkCompletionBlock) { - MTR_LOG_ERROR("%@ already scheduled in subscription pool for this device - ignoring: %@", self, description); + MTR_LOG("%@ already scheduled in subscription pool for this device - ignoring: %@", self, description); return; } @@ -1310,6 +1312,7 @@ - (void)_scheduleSubscriptionPoolWork:(dispatch_block_t)workBlock inNanoseconds: // In the case where a resubscription triggering event happened and already established, running the work block should result in a no-op MTRAsyncWorkItem * workItem = [[MTRAsyncWorkItem alloc] initWithQueue:self.queue]; [workItem setReadyHandler:^(id _Nonnull context, NSInteger retryCount, MTRAsyncWorkCompletionBlock _Nonnull completion) { + MTR_LOG("%@ - work item is ready to attempt pooled subscription"); os_unfair_lock_lock(&self->_lock); #ifdef DEBUG [self _callDelegatesWithBlock:^(id testDelegate) { @@ -1335,6 +1338,7 @@ - (void)_scheduleSubscriptionPoolWork:(dispatch_block_t)workBlock inNanoseconds: workBlock(); }]; [self->_deviceController.concurrentSubscriptionPool enqueueWorkItem:workItem description:description]; + MTR_LOG("%@ - enqueued in the subscription pool", self); }); } diff --git a/src/darwin/Framework/CHIP/MTRError_Internal.h b/src/darwin/Framework/CHIP/MTRError_Internal.h index c79cc17d95f198..af19f4888ff050 100644 --- a/src/darwin/Framework/CHIP/MTRError_Internal.h +++ b/src/darwin/Framework/CHIP/MTRError_Internal.h @@ -26,6 +26,10 @@ NS_ASSUME_NONNULL_BEGIN +#ifndef YES_NO +#define YES_NO(x) ((x) ? @"YES" : @"NO") +#endif + MTR_DIRECT_MEMBERS @interface MTRError : NSObject + (NSError *)errorWithCode:(MTRErrorCode)code; From 253823a658518ab328b605f6e09cd0ae0462fb1b Mon Sep 17 00:00:00 2001 From: Justin Wood Date: Mon, 8 Jul 2024 20:45:35 -1000 Subject: [PATCH 2/3] Apply suggestions from code review --- src/darwin/Framework/CHIP/MTRDevice.mm | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/darwin/Framework/CHIP/MTRDevice.mm b/src/darwin/Framework/CHIP/MTRDevice.mm index 2d4abce3cfd3cd..e065fb759b23cc 100644 --- a/src/darwin/Framework/CHIP/MTRDevice.mm +++ b/src/darwin/Framework/CHIP/MTRDevice.mm @@ -850,7 +850,7 @@ - (void)_addDelegate:(id)delegate queue:(dispatch_queue_t)que _initialSubscribeStart = [NSDate now]; } if ([self _deviceUsesThread]) { - MTR_LOG(" => %@ - device is a thread device, scheduling in pool"); + MTR_LOG(" => %@ - device is a thread device, scheduling in pool", self); [self _scheduleSubscriptionPoolWork:^{ std::lock_guard lock(self->_lock); [self _setupSubscriptionWithReason:@"delegate is set and scheduled subscription is happening"]; @@ -1312,7 +1312,7 @@ - (void)_scheduleSubscriptionPoolWork:(dispatch_block_t)workBlock inNanoseconds: // In the case where a resubscription triggering event happened and already established, running the work block should result in a no-op MTRAsyncWorkItem * workItem = [[MTRAsyncWorkItem alloc] initWithQueue:self.queue]; [workItem setReadyHandler:^(id _Nonnull context, NSInteger retryCount, MTRAsyncWorkCompletionBlock _Nonnull completion) { - MTR_LOG("%@ - work item is ready to attempt pooled subscription"); + MTR_LOG("%@ - work item is ready to attempt pooled subscription", self); os_unfair_lock_lock(&self->_lock); #ifdef DEBUG [self _callDelegatesWithBlock:^(id testDelegate) { From ad08d00434b74d3e3bf04f1f640d664549a9b6d3 Mon Sep 17 00:00:00 2001 From: Justin Wood Date: Mon, 8 Jul 2024 20:46:07 -1000 Subject: [PATCH 3/3] Update src/darwin/Framework/CHIP/MTRDevice.mm --- src/darwin/Framework/CHIP/MTRDevice.mm | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/darwin/Framework/CHIP/MTRDevice.mm b/src/darwin/Framework/CHIP/MTRDevice.mm index e065fb759b23cc..2ae8d5fc310d13 100644 --- a/src/darwin/Framework/CHIP/MTRDevice.mm +++ b/src/darwin/Framework/CHIP/MTRDevice.mm @@ -177,8 +177,8 @@ - (void)_deviceInternalStateChanged:(MTRDevice *)device; UnsolicitedMessageFromPublisherHandler unsolicitedMessageFromPublisherHandler, ReportBeginHandler reportBeginHandler, ReportEndHandler reportEndHandler) : MTRBaseSubscriptionCallback(attributeReportCallback, eventReportCallback, errorCallback, resubscriptionCallback, - subscriptionEstablishedHandler, onDoneHandler, unsolicitedMessageFromPublisherHandler, reportBeginHandler, - reportEndHandler) + subscriptionEstablishedHandler, onDoneHandler, unsolicitedMessageFromPublisherHandler, reportBeginHandler, + reportEndHandler) { }