Darwin changes for logging (project-chip#32053)

Author: woody-apple

src/darwin/Framework/CHIP/MTRDevice.mm

@@ -284,6 +284,8 @@ - (void)invalidate
 
     os_unfair_lock_lock(&self->_lock);
 
+    _state = MTRDeviceStateUnknown;
+
     _weakDelegate = nil;
 
     // Make sure we don't try to resubscribe if we have a pending resubscribe
@@ -343,20 +345,23 @@ - (void)_changeState:(MTRDeviceState)state
     _state = state;
     if (lastState != state) {
         if (state != MTRDeviceStateReachable) {
-            MTR_LOG_INFO("%@ State change %lu => %lu, set estimated start time to nil", self, static_cast<unsigned long>(lastState),
+            MTR_LOG_INFO("%@ reachability state change %lu => %lu, set estimated start time to nil", self, static_cast<unsigned long>(lastState),
                 static_cast<unsigned long>(state));
             _estimatedStartTime = nil;
             _estimatedStartTimeFromGeneralDiagnosticsUpTime = nil;
         } else {
             MTR_LOG_INFO(
-                "%@ State change %lu => %lu", self, static_cast<unsigned long>(lastState), static_cast<unsigned long>(state));
+                "%@ reachability state change %lu => %lu", self, static_cast<unsigned long>(lastState), static_cast<unsigned long>(state));
         }
         id<MTRDeviceDelegate> delegate = _weakDelegate.strongObject;
         if (delegate) {
             dispatch_async(_delegateQueue, ^{
                 [delegate device:self stateChanged:state];
             });
         }
+    } else {
+        MTR_LOG_INFO(
+            "%@ Not reporting reachability state change, since no change in state %lu => %lu", self, static_cast<unsigned long>(lastState), static_cast<unsigned long>(state));
     }
 }
 
@@ -592,14 +597,14 @@ - (void)_handleEventReport:(NSArray<NSDictionary<NSString *, id> *> *)eventRepor
         // If event time is of MTREventTimeTypeSystemUpTime type, then update estimated start time as needed
         NSNumber * eventTimeTypeNumber = eventDict[MTREventTimeTypeKey];
         if (!eventTimeTypeNumber) {
-            MTR_LOG_ERROR("Event %@ missing event time type", eventDict);
+            MTR_LOG_ERROR("%@ Event %@ missing event time type", self, eventDict);
             continue;
         }
         MTREventTimeType eventTimeType = (MTREventTimeType) eventTimeTypeNumber.unsignedIntegerValue;
         if (eventTimeType == MTREventTimeTypeSystemUpTime) {
             NSNumber * eventTimeValueNumber = eventDict[MTREventSystemUpTimeKey];
             if (!eventTimeValueNumber) {
-                MTR_LOG_ERROR("Event %@ missing event time value", eventDict);
+                MTR_LOG_ERROR("%@ Event %@ missing event time value", self, eventDict);
                 continue;
             }
             NSTimeInterval eventTimeValue = eventTimeValueNumber.doubleValue;
@@ -792,7 +797,7 @@ - (void)_setupSubscription
                    CHIP_ERROR err = readClient->SendAutoResubscribeRequest(std::move(readParams));
 
                    if (err != CHIP_NO_ERROR) {
-                       NSError * error = [MTRError errorForCHIPErrorCode:err];
+                       NSError * error = [MTRError errorForCHIPErrorCode:err logContext:self];
                        MTR_LOG_ERROR("%@ SendAutoResubscribeRequest error %@", self, error);
                        dispatch_async(self.queue, ^{
                            [self _handleSubscriptionError:error];
@@ -982,6 +987,8 @@ static BOOL AttributeHasChangesOmittedQuality(MTRAttributePath * attributePath)
         // Create work item, set ready handler to perform task, then enqueue the work
         MTRAsyncWorkItem * workItem = [[MTRAsyncWorkItem alloc] initWithQueue:self.queue];
         uint64_t workItemID = workItem.uniqueID; // capture only the ID, not the work item
+        NSNumber * nodeID = [self nodeID];
+
         [workItem setBatchingID:MTRDeviceWorkItemBatchingReadID data:readRequests handler:^(id opaqueDataCurrent, id opaqueDataNext) {
             mtr_hide(self); // don't capture self accidentally
             NSMutableArray<NSArray *> * readRequestsCurrent = opaqueDataCurrent;
@@ -991,23 +998,23 @@ 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", workItemID);
+                    MTR_LOG_INFO("Batching read attribute work item [%llu]: cannot add more work, item is full [%@:%@:%@:%@]", workItemID, nodeID, endpointID, clusterID, attributeID);
                     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", workItemID);
+                    MTR_LOG_INFO("Batching read attribute work item [%llu]: cannot add more work, parameter mismatch [%@:%@:%@:%@]", workItemID, nodeID, endpointID, clusterID, attributeID);
                     return outcome;
                 }
 
                 // merge the next item's first request into the current item's list
                 auto readItem = readRequestsNext.firstObject;
                 [readRequestsNext removeObjectAtIndex:0];
                 [readRequestsCurrent addObject:readItem];
-                MTR_LOG_INFO("Batching read attribute work item [%llu]: added %@ (now %tu requests total)",
-                    workItemID, readItem, readRequestsCurrent.count);
+                MTR_LOG_INFO("Batching read attribute work item [%llu]: added %@ (now %tu requests total) [%@:%@:%@:%@]",
+                    workItemID, readItem, readRequestsCurrent.count, nodeID, endpointID, clusterID, attributeID);
                 outcome = MTRBatchedPartially;
             }
             NSCAssert(readRequestsNext.count == 0, @"should have batched everything or returned early");
@@ -1017,7 +1024,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 %@", workItemID, readItem);
+                    MTR_LOG_DEFAULT("Read attribute work item [%llu] report duplicate %@ [%@:%@:%@:%@]", workItemID, readItem, nodeID, endpointID, clusterID, attributeID);
                     *isDuplicate = YES;
                     *stop = YES;
                     return;
@@ -1053,23 +1060,23 @@ 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: %@", workItemID, values);
+                                MTR_LOG_INFO("Read attribute work item [%llu] result: %@  [%@:%@:%@:%@]", workItemID, values, nodeID, endpointID, clusterID, attributeID);
                                 [self _handleAttributeReport:values];
                             }
 
                             // TODO: better retry logic
                             if (error && (retryCount < 2)) {
-                                MTR_LOG_ERROR("Read attribute work item [%llu] failed (will retry): %@", workItemID, error);
+                                MTR_LOG_ERROR("Read attribute work item [%llu] failed (will retry): %@   [%@:%@:%@:%@]", workItemID, error, nodeID, endpointID, clusterID, attributeID);
                                 completion(MTRAsyncWorkNeedsRetry);
                             } else {
                                 if (error) {
-                                    MTR_LOG_DEFAULT("Read attribute work item [%llu] failed (giving up): %@", workItemID, error);
+                                    MTR_LOG_DEFAULT("Read attribute work item [%llu] failed (giving up): %@   [%@:%@:%@:%@]", workItemID, error, nodeID, endpointID, clusterID, attributeID);
                                 }
                                 completion(MTRAsyncWorkComplete);
                             }
                         }];
         }];
-        [_asyncWorkQueue enqueueWorkItem:workItem descriptionWithFormat:@"read %@ %@ %@", endpointID, clusterID, attributeID];
+        [_asyncWorkQueue enqueueWorkItem:workItem descriptionWithFormat:@"read %@ %@ %@ %@", self.nodeID, endpointID, clusterID, attributeID];
     }
 
     return attributeValueToReturn;
@@ -1137,7 +1144,7 @@ - (void)writeAttributeWithEndpointID:(NSNumber *)endpointID
                                   completion(MTRAsyncWorkComplete);
                               }];
     }];
-    [_asyncWorkQueue enqueueWorkItem:workItem descriptionWithFormat:@"write %@ %@ %@", endpointID, clusterID, attributeID];
+    [_asyncWorkQueue enqueueWorkItem:workItem descriptionWithFormat:@"write %@ %@ %@ %@", self.nodeID, endpointID, clusterID, attributeID];
 }
 
 - (void)invokeCommandWithEndpointID:(NSNumber *)endpointID
@@ -1739,7 +1746,7 @@ - (void)setExpectedValues:(NSArray<NSDictionary<NSString *, id> *> *)values
     NSDate * expirationTime = [NSDate dateWithTimeIntervalSinceNow:expectedValueInterval.doubleValue / 1000];
 
     MTR_LOG_INFO(
-        "Setting expected values %@ with expiration time %f seconds from now", values, [expirationTime timeIntervalSinceNow]);
+        "%@ Setting expected values %@ with expiration time %f seconds from now", self, values, [expirationTime timeIntervalSinceNow]);
 
     os_unfair_lock_lock(&self->_lock);
 

src/darwin/Framework/CHIP/MTRError.h

@@ -104,31 +104,33 @@ typedef NS_ERROR_ENUM(MTRErrorDomain, MTRErrorCode){
 typedef NS_ERROR_ENUM(MTRInteractionErrorDomain, MTRInteractionErrorCode){
     // These values come from the general status code table in the Matter
     // Interaction Model specification.
-    MTRInteractionErrorCodeFailure                = 0x01,
-    MTRInteractionErrorCodeInvalidSubscription    = 0x7d,
-    MTRInteractionErrorCodeUnsupportedAccess      = 0x7e,
-    MTRInteractionErrorCodeUnsupportedEndpoint    = 0x7f,
-    MTRInteractionErrorCodeInvalidAction          = 0x80,
-    MTRInteractionErrorCodeUnsupportedCommand     = 0x81,
-    MTRInteractionErrorCodeInvalidCommand         = 0x85,
-    MTRInteractionErrorCodeUnsupportedAttribute   = 0x86,
-    MTRInteractionErrorCodeConstraintError        = 0x87,
-    MTRInteractionErrorCodeUnsupportedWrite       = 0x88,
-    MTRInteractionErrorCodeResourceExhausted      = 0x89,
-    MTRInteractionErrorCodeNotFound               = 0x8b,
-    MTRInteractionErrorCodeUnreportableAttribute  = 0x8c,
-    MTRInteractionErrorCodeInvalidDataType        = 0x8d,
-    MTRInteractionErrorCodeUnsupportedRead        = 0x8f,
-    MTRInteractionErrorCodeDataVersionMismatch    = 0x92,
-    MTRInteractionErrorCodeTimeout                = 0x94,
-    MTRInteractionErrorCodeBusy                   = 0x9c,
-    MTRInteractionErrorCodeUnsupportedCluster     = 0xc3,
-    MTRInteractionErrorCodeNoUpstreamSubscription = 0xc5,
-    MTRInteractionErrorCodeNeedsTimedInteraction  = 0xc6,
-    MTRInteractionErrorCodeUnsupportedEvent       = 0xc7,
-    MTRInteractionErrorCodePathsExhausted         = 0xc8,
-    MTRInteractionErrorCodeTimedRequestMismatch   = 0xc9,
-    MTRInteractionErrorCodeFailsafeRequired       = 0xca,
+    MTRInteractionErrorCodeFailure                                   = 0x01,
+    MTRInteractionErrorCodeInvalidSubscription                       = 0x7d,
+    MTRInteractionErrorCodeUnsupportedAccess                         = 0x7e,
+    MTRInteractionErrorCodeUnsupportedEndpoint                       = 0x7f,
+    MTRInteractionErrorCodeInvalidAction                             = 0x80,
+    MTRInteractionErrorCodeUnsupportedCommand                        = 0x81,
+    MTRInteractionErrorCodeInvalidCommand                            = 0x85,
+    MTRInteractionErrorCodeUnsupportedAttribute                      = 0x86,
+    MTRInteractionErrorCodeConstraintError                           = 0x87,
+    MTRInteractionErrorCodeUnsupportedWrite                          = 0x88,
+    MTRInteractionErrorCodeResourceExhausted                         = 0x89,
+    MTRInteractionErrorCodeNotFound                                  = 0x8b,
+    MTRInteractionErrorCodeUnreportableAttribute                     = 0x8c,
+    MTRInteractionErrorCodeInvalidDataType                           = 0x8d,
+    MTRInteractionErrorCodeUnsupportedRead                           = 0x8f,
+    MTRInteractionErrorCodeDataVersionMismatch                       = 0x92,
+    MTRInteractionErrorCodeTimeout                                   = 0x94,
+    MTRInteractionErrorCodeBusy                                      = 0x9c,
+    MTRInteractionErrorCodeUnsupportedCluster                        = 0xc3,
+    MTRInteractionErrorCodeNoUpstreamSubscription                    = 0xc5,
+    MTRInteractionErrorCodeNeedsTimedInteraction                     = 0xc6,
+    MTRInteractionErrorCodeUnsupportedEvent                          = 0xc7,
+    MTRInteractionErrorCodePathsExhausted                            = 0xc8,
+    MTRInteractionErrorCodeTimedRequestMismatch                      = 0xc9,
+    MTRInteractionErrorCodeFailsafeRequired                          = 0xca,
+    MTRInteractionErrorInvalidInState            MTR_NEWLY_AVAILABLE = 0xcb,
+    MTRInteractionErrorNoCommandResponse         MTR_NEWLY_AVAILABLE = 0xcc,
 };
 // clang-format on
 

src/darwin/Framework/CHIP/MTRError.mm

@@ -44,12 +44,17 @@ - (instancetype)initWithError:(CHIP_ERROR)error;
 @implementation MTRError
 
 + (NSError *)errorForCHIPErrorCode:(CHIP_ERROR)errorCode
+{
+    return [MTRError errorForCHIPErrorCode:errorCode logContext:nil];
+}
+
++ (NSError *)errorForCHIPErrorCode:(CHIP_ERROR)errorCode logContext:(id)contextToLog
 {
     if (errorCode == CHIP_NO_ERROR) {
         return nil;
     }
 
-    ChipLogError(Controller, "Creating NSError from %" CHIP_ERROR_FORMAT, errorCode.Format());
+    ChipLogError(Controller, "Creating NSError from %" CHIP_ERROR_FORMAT " (context: %@)", errorCode.Format(), contextToLog);
 
     if (errorCode.IsIMStatus()) {
         chip::app::StatusIB status(errorCode);

src/darwin/Framework/CHIP/MTRError_Internal.h

@@ -27,6 +27,7 @@ NS_ASSUME_NONNULL_BEGIN
 
 @interface MTRError : NSObject
 + (NSError * _Nullable)errorForCHIPErrorCode:(CHIP_ERROR)errorCode;
++ (NSError * _Nullable)errorForCHIPErrorCode:(CHIP_ERROR)errorCode logContext:(id _Nullable)contextToLog;
 + (NSError * _Nullable)errorForIMStatus:(const chip::app::StatusIB &)status;
 + (NSError * _Nullable)errorForIMStatusCode:(chip::Protocols::InteractionModel::Status)status;
 + (CHIP_ERROR)errorToCHIPErrorCode:(NSError * _Nullable)error;

src/darwin/Framework/CHIP/MTRSetupPayload.mm

@@ -235,7 +235,7 @@ + (MTRSetupPayload * _Nullable)setupPayloadWithOnboardingPayload:(NSString *)onb
 
     if (!validPayload) {
         if (error) {
-            *error = [MTRError errorForCHIPErrorCode:CHIP_ERROR_INVALID_ARGUMENT];
+            *error = [MTRError errorForCHIPErrorCode:CHIP_ERROR_INVALID_ARGUMENT logContext:onboardingPayload];
         }
         return nil;
     }
@@ -336,23 +336,23 @@ - (NSString * _Nullable)qrCodeString:(NSError * __autoreleasing *)error
     if (self.commissioningFlow == MTRCommissioningFlowInvalid) {
         // No idea how to map this to the standard codes.
         if (error != nil) {
-            *error = [MTRError errorForCHIPErrorCode:CHIP_ERROR_INCORRECT_STATE];
+            *error = [MTRError errorForCHIPErrorCode:CHIP_ERROR_INCORRECT_STATE logContext:@"invalid flow"];
         }
         return nil;
     }
 
     if (self.hasShortDiscriminator) {
         // Can't create a QR code with a short discriminator.
         if (error != nil) {
-            *error = [MTRError errorForCHIPErrorCode:CHIP_ERROR_INCORRECT_STATE];
+            *error = [MTRError errorForCHIPErrorCode:CHIP_ERROR_INCORRECT_STATE logContext:@"cannot create a QR code with a short descrimintor"];
         }
         return nil;
     }
 
     if (self.discoveryCapabilities == MTRDiscoveryCapabilitiesUnknown) {
         // Can't create a QR code if we don't know the discovery capabilities.
         if (error != nil) {
-            *error = [MTRError errorForCHIPErrorCode:CHIP_ERROR_INCORRECT_STATE];
+            *error = [MTRError errorForCHIPErrorCode:CHIP_ERROR_INCORRECT_STATE logContext:@"cannot create a QR code with unknown discovery capabilities"];
         }
         return nil;
     }

src/darwin/Framework/Matter.xcodeproj/project.pbxproj

@@ -1648,7 +1648,7 @@
 			isa = PBXProject;
 			attributes = {
 				BuildIndependentTargetsInParallel = YES;
-				LastUpgradeCheck = 1140;
+				LastUpgradeCheck = 1500;
 				ORGANIZATIONNAME = CHIP;
 				TargetAttributes = {
 					037C3CA42991A44B00B7EEE2 = {

src/darwin/Framework/Matter.xcodeproj/xcshareddata/xcschemes/Matter Framework Tests.xcscheme

@@ -1,6 +1,6 @@
 <?xml version="1.0" encoding="UTF-8"?>
 <Scheme
-   LastUpgradeVersion = "1200"
+   LastUpgradeVersion = "1500"
    version = "1.7">
    <BuildAction
       parallelizeBuildables = "YES"
@@ -38,8 +38,6 @@
                BlueprintName = "MatterTests"
                ReferencedContainer = "container:Matter.xcodeproj">
             </BuildableReference>
-            <SkippedTests>
-            </SkippedTests>
          </TestableReference>
       </Testables>
    </TestAction>

src/darwin/Framework/Matter.xcodeproj/xcshareddata/xcschemes/Matter Framework.xcscheme

@@ -1,6 +1,6 @@
 <?xml version="1.0" encoding="UTF-8"?>
 <Scheme
-   LastUpgradeVersion = "1200"
+   LastUpgradeVersion = "1500"
    version = "1.7">
    <BuildAction
       parallelizeBuildables = "YES"

src/darwin/Framework/Matter.xcodeproj/xcshareddata/xcschemes/darwin-framework-tool.xcscheme

@@ -1,6 +1,6 @@
 <?xml version="1.0" encoding="UTF-8"?>
 <Scheme
-   LastUpgradeVersion = "1410"
+   LastUpgradeVersion = "1500"
    version = "1.7">
    <BuildAction
       parallelizeBuildables = "YES"
@@ -38,7 +38,6 @@
       useCustomWorkingDirectory = "NO"
       ignoresPersistentStateOnLaunch = "NO"
       debugDocumentVersioning = "YES"
-      debugServiceExtension = ""
       allowLocationSimulation = "YES"
       viewDebuggingEnabled = "No">
       <BuildableProductRunnable