Adding logging to Darwin (project-chip#34241)

* Adding logging so we can debug stuff...

* Apply suggestions from code review

* Update src/darwin/Framework/CHIP/MTRDevice.mm

Author: woody-apple

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,

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;
     }
 }

src/darwin/Framework/CHIP/MTRDevice.mm

@@ -844,11 +844,13 @@ - (void)_addDelegate:(id<MTRDeviceDelegate>)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);
             [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", self);
             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);
     });
 }
 

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;