[Darwin] More logging for MTRDevice persistence (#32351)

* [Darwin] More logging for MTRDevice persistence * Type cast NSUInteger for format string * restyled --------- Co-authored-by: Justin Wood <[email protected]>
project-chip · Mar 7, 2024 · 5568158 · 5568158
1 parent aae9722
commit 5568158
Show file tree

Hide file tree

Showing 5 changed files with 71 additions and 19 deletions.
diff --git a/src/darwin/Framework/CHIP/MTRDevice.mm b/src/darwin/Framework/CHIP/MTRDevice.mm
@@ -939,6 +939,7 @@ - (void)_handleEventReport:(NSArray<NSDictionary<NSString *, id> *> *)eventRepor
  }
  }
  }
+ MTR_LOG_INFO("%@ _getCachedDataVersions dataVersions count: %lu readCache count: %lu", self, dataVersions.count, _readCache.count);
  os_unfair_lock_unlock(&self->_lock);
 
  return dataVersions;
@@ -1983,6 +1984,7 @@ - (NSArray *)_getAttributesToReportWithReportedValues:(NSArray<NSDictionary<NSSt
 
 - (void)setAttributeValues:(NSArray<NSDictionary *> *)attributeValues reportChanges:(BOOL)reportChanges
 {
+ MTR_LOG_INFO("%@ setAttributeValues count: %lu reportChanges: %d", self, attributeValues.count, reportChanges);
  os_unfair_lock_lock(&self->_lock);
 
  if (reportChanges) {

diff --git a/src/darwin/Framework/CHIP/MTRDeviceController.mm b/src/darwin/Framework/CHIP/MTRDeviceController.mm
@@ -887,7 +887,8 @@ - (MTRDevice *)deviceForNodeID:(NSNumber *)nodeID
 
  // Load persisted attributes if they exist.
  NSArray * attributesFromCache = [_controllerDataStore getStoredAttributesForNodeID:nodeID];
- if (attributesFromCache) {
+ MTR_LOG_INFO("Loaded %lu attributes from storage for %@", attributesFromCache.count, deviceToReturn);
+ if (attributesFromCache.count) {
  [deviceToReturn setAttributeValues:attributesFromCache reportChanges:NO];
  }
  }

diff --git a/src/darwin/Framework/CHIP/MTRDeviceControllerDataStore.mm b/src/darwin/Framework/CHIP/MTRDeviceControllerDataStore.mm
@@ -503,6 +503,7 @@ - (void)_pruneEmptyStoredAttributesBranches
  NSMutableArray<NSNumber *> * nodeIndex = [self _fetchNodeIndex].mutableCopy;
  NSUInteger nodeIndexCount = nodeIndex.count;
 
+ NSUInteger storeFailures = 0;
  for (NSNumber * nodeID in nodeIndex) {
  // Fetch endpoint index
  NSMutableArray<NSNumber *> * endpointIndex = [self _fetchEndpointIndexForNodeID:nodeID].mutableCopy;
@@ -529,35 +530,55 @@ - (void)_pruneEmptyStoredAttributesBranches
  if (!attributeIndex.count) {
  [clusterIndex removeObject:clusterID];
  } else if (attributeIndex.count != attributeIndexCount) {
- [self _storeAttributeIndex:attributeIndex forNodeID:nodeID endpointID:endpointID clusterID:clusterID];
+ BOOL success = [self _storeAttributeIndex:attributeIndex forNodeID:nodeID endpointID:endpointID clusterID:clusterID];
+ if (!success) {
+ storeFailures++;
+ MTR_LOG_INFO("Store failed for attributeIndex");
+ }
  }
  }
 
  if (!clusterIndex.count) {
  [endpointIndex removeObject:endpointID];
  } else if (clusterIndex.count != clusterIndexCount) {
- [self _storeClusterIndex:clusterIndex forNodeID:nodeID endpointID:endpointID];
+ BOOL success = [self _storeClusterIndex:clusterIndex forNodeID:nodeID endpointID:endpointID];
+ if (!success) {
+ storeFailures++;
+ MTR_LOG_INFO("Store failed for clusterIndex");
+ }
  }
  }
 
  if (!endpointIndex.count) {
  [nodeIndex removeObject:nodeID];
  } else if (endpointIndex.count != endpointIndexCount) {
- [self _storeEndpointIndex:endpointIndex forNodeID:nodeID];
+ BOOL success = [self _storeEndpointIndex:endpointIndex forNodeID:nodeID];
+ if (!success) {
+ storeFailures++;
+ MTR_LOG_INFO("Store failed for endpointIndex");
+ }
  }
  }
 
  if (!nodeIndex.count) {
  [self _deleteNodeIndex];
  } else if (nodeIndex.count != nodeIndexCount) {
- [self _storeNodeIndex:nodeIndex];
+ BOOL success = [self _storeNodeIndex:nodeIndex];
+ if (!success) {
+ storeFailures++;
+ MTR_LOG_INFO("Store failed for nodeIndex");
+ }
+ }
+
+ if (storeFailures) {
+ MTR_LOG_ERROR("Store failed in _pruneEmptyStoredAttributesBranches: %lu", (unsigned long) storeFailures);
  }
 }
 
 - (void)storeAttributeValues:(NSArray<NSDictionary *> *)dataValues forNodeID:(NSNumber *)nodeID
 {
  dispatch_async(_storageDelegateQueue, ^{
- BOOL anyStoreFailed = NO;
+ NSUInteger storeFailures = 0;
 
  for (NSDictionary * dataValue in dataValues) {
  MTRAttributePath * path = dataValue[MTRAttributePathKey];
@@ -573,7 +594,8 @@ - (void)storeAttributeValues:(NSArray<NSDictionary *> *)dataValues forNodeID:(NS
  storeFailed = ![self _storeNodeIndex:[nodeIndex arrayByAddingObject:nodeID]];
  }
  if (storeFailed) {
- anyStoreFailed = YES;
+ storeFailures++;
+ MTR_LOG_INFO("Store failed for nodeIndex");
  continue;
  }
 
@@ -586,7 +608,8 @@ - (void)storeAttributeValues:(NSArray<NSDictionary *> *)dataValues forNodeID:(NS
  storeFailed = ![self _storeEndpointIndex:[endpointIndex arrayByAddingObject:path.endpoint] forNodeID:nodeID];
  }
  if (storeFailed) {
- anyStoreFailed = YES;
+ storeFailures++;
+ MTR_LOG_INFO("Store failed for endpointIndex");
  continue;
  }
 
@@ -599,7 +622,8 @@ - (void)storeAttributeValues:(NSArray<NSDictionary *> *)dataValues forNodeID:(NS
  storeFailed = ![self _storeClusterIndex:[clusterIndex arrayByAddingObject:path.cluster] forNodeID:nodeID endpointID:path.endpoint];
  }
  if (storeFailed) {
- anyStoreFailed = YES;
+ storeFailures++;
+ MTR_LOG_INFO("Store failed for clusterIndex");
  continue;
  }
 
@@ -615,20 +639,23 @@ - (void)storeAttributeValues:(NSArray<NSDictionary *> *)dataValues forNodeID:(NS
  storeFailed = ![self _storeAttributeIndex:[attributeIndex arrayByAddingObject:path.attribute] forNodeID:nodeID endpointID:path.endpoint clusterID:path.cluster];
  }
  if (storeFailed) {
- anyStoreFailed = YES;
+ storeFailures++;
+ MTR_LOG_INFO("Store failed for attributeIndex");
  continue;
  }
 
  // Store value
  storeFailed = [self _storeAttributeValue:value forNodeID:nodeID endpointID:path.endpoint clusterID:path.cluster attributeID:path.attribute];
  if (storeFailed) {
- anyStoreFailed = YES;
+ storeFailures++;
+ MTR_LOG_INFO("Store failed for attribute value");
  }
  }
 
  // In the rare event that store fails, allow all attribute store attempts to go through and prune empty branches at the end altogether.
- if (anyStoreFailed) {
+ if (storeFailures) {
  [self _pruneEmptyStoredAttributesBranches];
+ MTR_LOG_ERROR("Store failed in -storeAttributeValues:forNodeID: %lu", (unsigned long) storeFailures);
  }
  });
 }

diff --git a/...HIP/MTRDeviceControllerLocalTestStorage.m → ...IP/MTRDeviceControllerLocalTestStorage.mm b/...HIP/MTRDeviceControllerLocalTestStorage.m → ...IP/MTRDeviceControllerLocalTestStorage.mm
@@ -16,6 +16,7 @@
  */
 
 #import "MTRDeviceControllerLocalTestStorage.h"
+#import "MTRLogging_Internal.h"
 
 #if MTR_PER_CONTROLLER_STORAGE_ENABLED
 
@@ -36,12 +37,18 @@ + (void)setLocalTestStorageEnabled:(BOOL)localTestStorageEnabled
 {
  NSUserDefaults * defaults = [[NSUserDefaults alloc] initWithSuiteName:kLocalTestUserDefaultDomain];
  [defaults setBool:localTestStorageEnabled forKey:kLocalTestUserDefaultEnabledKey];
+ MTR_LOG_INFO("MTRDeviceControllerLocalTestStorage setLocalTestStorageEnabled %d", localTestStorageEnabled);
+ BOOL storedLocalTestStorageEnabled = [defaults boolForKey:kLocalTestUserDefaultEnabledKey];
+ if (storedLocalTestStorageEnabled != localTestStorageEnabled) {
+ MTR_LOG_ERROR("MTRDeviceControllerLocalTestStorage setLocalTestStorageEnabled %d failed", localTestStorageEnabled);
+ }
 }
 
 - (instancetype)initWithPassThroughStorage:(id<MTRDeviceControllerStorageDelegate>)passThroughStorage
 {
  if (self = [super init]) {
  _passThroughStorage = passThroughStorage;
+ MTR_LOG_INFO("MTRDeviceControllerLocalTestStorage initialized with pass-through storage %@", passThroughStorage);
  }
  return self;
 }
@@ -58,7 +65,12 @@ - (instancetype)initWithPassThroughStorage:(id<MTRDeviceControllerStorageDelegat
  id value = [NSKeyedUnarchiver unarchivedObjectOfClasses:MTRDeviceControllerStorageClasses() fromData:storedData error:&error];
  return value;
  } else {
- return [_passThroughStorage controller:controller valueForKey:key securityLevel:securityLevel sharingType:sharingType];
+ if (_passThroughStorage) {
+ return [_passThroughStorage controller:controller valueForKey:key securityLevel:securityLevel sharingType:sharingType];
+ } else {
+ MTR_LOG_INFO("MTRDeviceControllerLocalTestStorage valueForKey: shared type but no pass-through storage");
+ return nil;
+ }
  }
 }
 
@@ -75,7 +87,12 @@ - (BOOL)controller:(MTRDeviceController *)controller
  [defaults setObject:data forKey:key];
  return YES;
  } else {
- return [_passThroughStorage controller:controller storeValue:value forKey:key securityLevel:securityLevel sharingType:sharingType];
+ if (_passThroughStorage) {
+ return [_passThroughStorage controller:controller storeValue:value forKey:key securityLevel:securityLevel sharingType:sharingType];
+ } else {
+ MTR_LOG_INFO("MTRDeviceControllerLocalTestStorage storeValue: shared type but no pass-through storage");
+ return NO;
+ }
  }
 }
 
@@ -89,7 +106,12 @@ - (BOOL)controller:(MTRDeviceController *)controller
  [defaults removeObjectForKey:key];
  return YES;
  } else {
- return [_passThroughStorage controller:controller removeValueForKey:key securityLevel:securityLevel sharingType:sharingType];
+ if (_passThroughStorage) {
+ return [_passThroughStorage controller:controller removeValueForKey:key securityLevel:securityLevel sharingType:sharingType];
+ } else {
+ MTR_LOG_INFO("MTRDeviceControllerLocalTestStorage removeValueForKey: shared type but no pass-through storage");
+ return NO;
+ }
  }
 }
 @end

diff --git a/src/darwin/Framework/Matter.xcodeproj/project.pbxproj b/src/darwin/Framework/Matter.xcodeproj/project.pbxproj
@@ -240,7 +240,7 @@
  5ACDDD7D27CD16D200EFD68A /* MTRClusterStateCacheContainer.mm in Sources */ = {isa = PBXBuildFile; fileRef = 5ACDDD7C27CD16D200EFD68A /* MTRClusterStateCacheContainer.mm */; };
  5ACDDD7E27CD3F3A00EFD68A /* MTRClusterStateCacheContainer_Internal.h in Headers */ = {isa = PBXBuildFile; fileRef = 5ACDDD7B27CD14AF00EFD68A /* MTRClusterStateCacheContainer_Internal.h */; };
  5AE6D4E427A99041001F2493 /* MTRDeviceTests.m in Sources */ = {isa = PBXBuildFile; fileRef = 5AE6D4E327A99041001F2493 /* MTRDeviceTests.m */; };
- 75139A6F2B7FE5E900E3A919 /* MTRDeviceControllerLocalTestStorage.m in Sources */ = {isa = PBXBuildFile; fileRef = 75139A6E2B7FE5E900E3A919 /* MTRDeviceControllerLocalTestStorage.m */; };
+ 75139A6F2B7FE5E900E3A919 /* MTRDeviceControllerLocalTestStorage.mm in Sources */ = {isa = PBXBuildFile; fileRef = 75139A6E2B7FE5E900E3A919 /* MTRDeviceControllerLocalTestStorage.mm */; };
  75139A702B7FE68C00E3A919 /* MTRDeviceControllerLocalTestStorage.h in Headers */ = {isa = PBXBuildFile; fileRef = 75139A6D2B7FE5D600E3A919 /* MTRDeviceControllerLocalTestStorage.h */; settings = {ATTRIBUTES = (Private, ); }; };
  7534F12828BFF20300390851 /* MTRDeviceAttestationDelegate.mm in Sources */ = {isa = PBXBuildFile; fileRef = 7534F12628BFF20300390851 /* MTRDeviceAttestationDelegate.mm */; };
  7534F12928BFF20300390851 /* MTRDeviceAttestationDelegate_Internal.h in Headers */ = {isa = PBXBuildFile; fileRef = 7534F12728BFF20300390851 /* MTRDeviceAttestationDelegate_Internal.h */; };
@@ -640,7 +640,7 @@
  5AE6D4E327A99041001F2493 /* MTRDeviceTests.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = MTRDeviceTests.m; sourceTree = "<group>"; };
  75139A6C2B7FE19100E3A919 /* MTRTestDeclarations.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; path = MTRTestDeclarations.h; sourceTree = "<group>"; };
  75139A6D2B7FE5D600E3A919 /* MTRDeviceControllerLocalTestStorage.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; path = MTRDeviceControllerLocalTestStorage.h; sourceTree = "<group>"; };
- 75139A6E2B7FE5E900E3A919 /* MTRDeviceControllerLocalTestStorage.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = MTRDeviceControllerLocalTestStorage.m; sourceTree = "<group>"; };
+ 75139A6E2B7FE5E900E3A919 /* MTRDeviceControllerLocalTestStorage.mm */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.cpp.objcpp; path = MTRDeviceControllerLocalTestStorage.mm; sourceTree = "<group>"; };
  7534F12628BFF20300390851 /* MTRDeviceAttestationDelegate.mm */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.cpp.objcpp; path = MTRDeviceAttestationDelegate.mm; sourceTree = "<group>"; };
  7534F12728BFF20300390851 /* MTRDeviceAttestationDelegate_Internal.h */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.h; path = MTRDeviceAttestationDelegate_Internal.h; sourceTree = "<group>"; };
  754F3DF327FBB94B00E60580 /* MTREventTLVValueDecoder_Internal.h */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.h; path = MTREventTLVValueDecoder_Internal.h; sourceTree = "<group>"; };
@@ -1248,7 +1248,7 @@
  5136661128067D540025EDAE /* MTRDeviceControllerFactory_Internal.h */,
  5136661028067D540025EDAE /* MTRDeviceControllerFactory.mm */,
  75139A6D2B7FE5D600E3A919 /* MTRDeviceControllerLocalTestStorage.h */,
- 75139A6E2B7FE5E900E3A919 /* MTRDeviceControllerLocalTestStorage.m */,
+ 75139A6E2B7FE5E900E3A919 /* MTRDeviceControllerLocalTestStorage.mm */,
  5A6FEC8D27B5624E00F25F42 /* MTRDeviceControllerOverXPC.h */,
  5A830D6B27CFCF590053B85D /* MTRDeviceControllerOverXPC_Internal.h */,
  5A6FEC8F27B563D900F25F42 /* MTRDeviceControllerOverXPC.mm */,
@@ -1851,7 +1851,7 @@
  75B765C32A1D82D30014719B /* MTRAttributeSpecifiedCheck.mm in Sources */,
  AF5F90FF2878D351005503FA /* MTROTAProviderDelegateBridge.mm in Sources */,
  516415FF2B6B132200D5CE11 /* DataModelHandler.cpp in Sources */,
- 75139A6F2B7FE5E900E3A919 /* MTRDeviceControllerLocalTestStorage.m in Sources */,
+ 75139A6F2B7FE5E900E3A919 /* MTRDeviceControllerLocalTestStorage.mm in Sources */,
  51E95DFC2A78443C00A434F0 /* MTRSessionResumptionStorageBridge.mm in Sources */,
  514C79ED2B62ADCD00DD6D7B /* ember-compatibility-functions.cpp in Sources */,
  7534F12828BFF20300390851 /* MTRDeviceAttestationDelegate.mm in Sources */,