Fix up guarantees around the "device cache primed" notification.

We should be dispatching this only if we did not previously have a primed device
cache.

testAttributeReportWithValue was renamed, because methods starting with "test"
are run as actual tests, and that's not what it's supposed to be doing.

Author: bzbarsky-apple

src/darwin/Framework/CHIP/MTRDevice.mm

@@ -376,7 +376,11 @@ @implementation MTRDevice {
 #ifdef DEBUG
     NSUInteger _unitTestAttributesReportedSinceLastCheck;
 #endif
-    BOOL _delegateDeviceCachePrimedCalled;
+
+    // _deviceCachePrimed is true if we have the data that comes from an initial
+    // subscription priming report (whether it came from storage or from our
+    // subscription).
+    BOOL _deviceCachePrimed;
 
     // _persistedClusterData stores data that we have already persisted (when we have
     // cluster data persistence enabled).  Nil when we have no persistence enabled.
@@ -736,11 +740,6 @@ - (void)setDelegate:(id<MTRDeviceDelegate>)delegate queue:(dispatch_queue_t)queu
     _weakDelegate = [MTRWeakReference weakReferenceWithObject:delegate];
     _delegateQueue = queue;
 
-    // If Check if cache is already primed and client hasn't been informed yet, call the -deviceCachePrimed: callback
-    if (!_delegateDeviceCachePrimedCalled && [self _isCachePrimedWithInitialConfigurationData]) {
-        [self _callDelegateDeviceCachePrimed];
-    }
-
     if (setUpSubscription) {
         _initialSubscribeStart = [NSDate now];
         if ([self _deviceUsesThread]) {
@@ -915,7 +914,7 @@ - (BOOL)_callDelegateWithBlock:(void (^)(id<MTRDeviceDelegate>))block
 - (void)_callDelegateDeviceCachePrimed
 {
     os_unfair_lock_assert_owner(&self->_lock);
-    _delegateDeviceCachePrimedCalled = [self _callDelegateWithBlock:^(id<MTRDeviceDelegate> delegate) {
+    [self _callDelegateWithBlock:^(id<MTRDeviceDelegate> delegate) {
         if ([delegate respondsToSelector:@selector(deviceCachePrimed:)]) {
             [delegate deviceCachePrimed:self];
         }
@@ -994,11 +993,6 @@ - (void)_handleSubscriptionEstablished
         [self _changeInternalState:MTRInternalDeviceStateInitialSubscriptionEstablished];
     }
 
-    // As subscription is established, check if the delegate needs to be informed
-    if (!_delegateDeviceCachePrimedCalled) {
-        [self _callDelegateDeviceCachePrimed];
-    }
-
     [self _changeState:MTRDeviceStateReachable];
 
     // No need to monitor connectivity after subscription establishment
@@ -1480,6 +1474,12 @@ - (void)_scheduleClusterDataPersistence
         return;
     }
 
+    // If we have nothing stored at all yet, store directly, so we move into a
+    // primed state.
+    if (!_deviceCachePrimed) {
+        [self _persistClusterData];
+    }
+
     // Ensure there is an array to keep the most recent report times
     if (!_mostRecentReportTimes) {
         _mostRecentReportTimes = [NSMutableArray array];
@@ -1525,7 +1525,7 @@ - (void)_scheduleClusterDataPersistence
 
             // Set current multiplier to [1, MaxMultiplier]
             _reportToPersistenceDelayCurrentMultiplier = 1 + (proportionTowardMinThreshold * (_storageBehaviorConfiguration.reportToPersistenceDelayMaxMultiplier - 1));
-            MTR_LOG("%@ storage behavior: device reporting frequently - setting delay multiplied to %lf", self, _reportToPersistenceDelayCurrentMultiplier);
+            MTR_LOG("%@ storage behavior: device reporting frequently - setting delay multiplier to %lf", self, _reportToPersistenceDelayCurrentMultiplier);
         } else {
             _reportToPersistenceDelayCurrentMultiplier = 1;
         }
@@ -1601,6 +1601,19 @@ - (void)_handleReportEnd
         _deviceConfigurationChanged = NO;
     }
 
+    // Do this after the _deviceConfigurationChanged check, so that we don't
+    // call deviceConfigurationChanged: immediately after telling our delegate
+    // we are now primed.
+    //
+    // TODO: Maybe we shouldn't dispatch deviceConfigurationChanged: for the
+    // initial priming bits?
+    if (!_deviceCachePrimed) {
+        // This is the end of the priming sequence of data reports, so we have
+        // all the data for the device now.
+        _deviceCachePrimed = YES;
+        [self _callDelegateDeviceCachePrimed];
+    }
+
 // For unit testing only
 #ifdef DEBUG
     id delegate = _weakDelegate.strongObject;
@@ -3165,10 +3178,9 @@ - (void)setPersistedClusterData:(NSDictionary<MTRClusterPath *, MTRDeviceCluster
         [_persistedClusterData setObject:clusterData[clusterPath] forKey:clusterPath];
     }
 
-    // If cache is set from storage and is primed with initial configuration data, then assume the client had beeen informed in the past, and mark that the callback has been called
-    if ([self _isCachePrimedWithInitialConfigurationData]) {
-        _delegateDeviceCachePrimedCalled = YES;
-    }
+    // We have some stored data.  Since we don't store data until the end of the
+    // initial priming report, our device cache must be primed.
+    _deviceCachePrimed = YES;
 }
 
 - (void)_setLastInitialSubscribeLatency:(id)latency
@@ -3218,7 +3230,7 @@ - (void)_storePersistedDeviceData
 - (BOOL)deviceCachePrimed
 {
     std::lock_guard lock(_lock);
-    return [self _isCachePrimedWithInitialConfigurationData];
+    return _deviceCachePrimed;
 }
 
 // If value is non-nil, associate with expectedValueID
@@ -3395,47 +3407,6 @@ - (void)_removeExpectedValueForAttributePath:(MTRAttributePath *)attributePath e
     }
 }
 
-// This method checks if there is a need to inform delegate that the attribute cache has been "primed"
-- (BOOL)_isCachePrimedWithInitialConfigurationData
-{
-    os_unfair_lock_assert_owner(&self->_lock);
-
-    // Check if root node descriptor exists
-    MTRDeviceDataValueDictionary rootDescriptorPartsListDataValue = [self _cachedAttributeValueForPath:[MTRAttributePath attributePathWithEndpointID:@(kRootEndpointId) clusterID:@(MTRClusterIDTypeDescriptorID) attributeID:@(MTRAttributeIDTypeClusterDescriptorAttributePartsListID)]];
-    if (!rootDescriptorPartsListDataValue || ![MTRArrayValueType isEqualToString:rootDescriptorPartsListDataValue[MTRTypeKey]]) {
-        return NO;
-    }
-    NSArray * partsList = rootDescriptorPartsListDataValue[MTRValueKey];
-    if (![partsList isKindOfClass:[NSArray class]] || !partsList.count) {
-        MTR_LOG_ERROR("%@ unexpected type %@ for parts list %@", self, [partsList class], partsList);
-        return NO;
-    }
-
-    // Check if we have cached descriptor clusters for each listed endpoint
-    for (NSDictionary * endpointDictionary in partsList) {
-        NSDictionary * endpointDataValue = endpointDictionary[MTRDataKey];
-        if (![endpointDataValue isKindOfClass:[NSDictionary class]]) {
-            MTR_LOG_ERROR("%@ unexpected parts list dictionary %@ data value class %@", self, endpointDictionary, [endpointDataValue class]);
-            continue;
-        }
-        if (![MTRUnsignedIntegerValueType isEqual:endpointDataValue[MTRTypeKey]]) {
-            MTR_LOG_ERROR("%@ unexpected parts list data value %@ item type %@", self, endpointDataValue, endpointDataValue[MTRTypeKey]);
-            continue;
-        }
-        NSNumber * endpoint = endpointDataValue[MTRValueKey];
-        if (![endpoint isKindOfClass:[NSNumber class]]) {
-            MTR_LOG_ERROR("%@ unexpected parts list item value class %@", self, [endpoint class]);
-            continue;
-        }
-        MTRDeviceDataValueDictionary descriptorDeviceTypeListDataValue = [self _cachedAttributeValueForPath:[MTRAttributePath attributePathWithEndpointID:endpoint clusterID:@(MTRClusterIDTypeDescriptorID) attributeID:@(MTRAttributeIDTypeClusterDescriptorAttributeDeviceTypeListID)]];
-        if (![MTRArrayValueType isEqualToString:descriptorDeviceTypeListDataValue[MTRTypeKey]] || !descriptorDeviceTypeListDataValue[MTRValueKey]) {
-            return NO;
-        }
-    }
-
-    return YES;
-}
-
 - (MTRBaseDevice *)newBaseDevice
 {
     return [MTRBaseDevice deviceWithNodeID:self.nodeID controller:self.deviceController];

src/darwin/Framework/CHIPTests/MTRDeviceTests.m

@@ -3669,7 +3669,7 @@ - (void)test035_TestMTRDeviceSubscriptionNotEstablishedOverXPC
     XCTAssertEqual([device _getInternalState], MTRInternalDeviceStateUnsubscribed);
 }
 
-- (NSArray<NSDictionary<NSString *, id> *> *)testAttributeReportWithValue:(unsigned int)testValue
+- (NSArray<NSDictionary<NSString *, id> *> *)_testAttributeReportWithValue:(unsigned int)testValue
 {
     return @[ @{
         MTRAttributePathKey : [MTRAttributePath attributePathWithEndpointID:@(0) clusterID:@(MTRClusterIDTypeLevelControlID) attributeID:@(MTRAttributeIDTypeClusterLevelControlAttributeCurrentLevelID)],
@@ -3696,7 +3696,7 @@ - (void)test036_TestStorageBehaviorConfiguration
     __block NSDate * reportEndTime = nil;
     __block NSDate * dataPersistedTime = nil;
 
-    XCTestExpectation * dataPersisted1 = [self expectationWithDescription:@"data persisted 1"];
+    XCTestExpectation * dataPersistedInitial = [self expectationWithDescription:@"data persisted initial"];
     delegate.onReportEnd = ^() {
         os_unfair_lock_lock(&lock);
         if (!reportEndTime) {
@@ -3711,7 +3711,7 @@ - (void)test036_TestStorageBehaviorConfiguration
             dataPersistedTime = [NSDate now];
         }
         os_unfair_lock_unlock(&lock);
-        [dataPersisted1 fulfill];
+        [dataPersistedInitial fulfill];
     };
 
     // Do not subscribe - only inject sequence of reports to control the timing
@@ -3732,11 +3732,29 @@ - (void)test036_TestStorageBehaviorConfiguration
 
     [device setDelegate:delegate queue:queue];
 
-    // Use a mutable dictionary so the data value can be easily changed between reports
+    // Use a counter that will be incremented for each report as the value.
     unsigned int currentTestValue = 1;
 
+    // Initial setup: Inject report and see that the attribute persisted.  No delay is
+    // expected for the first (priming) report.
+    [device unitTestInjectAttributeReport:[self _testAttributeReportWithValue:currentTestValue++] fromSubscription:YES];
+
+    [self waitForExpectations:@[ dataPersistedInitial ] timeout:60];
+
+    XCTestExpectation * dataPersisted1 = [self expectationWithDescription:@"data persisted 1"];
+    delegate.onClusterDataPersisted = ^{
+        os_unfair_lock_lock(&lock);
+        if (!dataPersistedTime) {
+            dataPersistedTime = [NSDate now];
+        }
+        os_unfair_lock_unlock(&lock);
+        [dataPersisted1 fulfill];
+    };
+
     // Test 1: Inject report and see that the attribute persisted, with a delay
-    [device unitTestInjectAttributeReport:[self testAttributeReportWithValue:currentTestValue++] fromSubscription:YES];
+    reportEndTime = nil;
+    dataPersistedTime = nil;
+    [device unitTestInjectAttributeReport:[self _testAttributeReportWithValue:currentTestValue++] fromSubscription:YES];
 
     [self waitForExpectations:@[ dataPersisted1 ] timeout:60];
 
@@ -3762,20 +3780,20 @@ - (void)test036_TestStorageBehaviorConfiguration
     // Test 2: Inject multiple reports with delay and see that the attribute persisted eventually
     reportEndTime = nil;
     dataPersistedTime = nil;
-    [device unitTestInjectAttributeReport:[self testAttributeReportWithValue:currentTestValue++] fromSubscription:YES];
+    [device unitTestInjectAttributeReport:[self _testAttributeReportWithValue:currentTestValue++] fromSubscription:YES];
 
     double frequentReportMultiplier = 0.5;
     usleep((useconds_t) (baseTestDelayTime * frequentReportMultiplier * USEC_PER_SEC));
-    [device unitTestInjectAttributeReport:[self testAttributeReportWithValue:currentTestValue++] fromSubscription:YES];
+    [device unitTestInjectAttributeReport:[self _testAttributeReportWithValue:currentTestValue++] fromSubscription:YES];
 
     usleep((useconds_t) (baseTestDelayTime * frequentReportMultiplier * USEC_PER_SEC));
-    [device unitTestInjectAttributeReport:[self testAttributeReportWithValue:currentTestValue++] fromSubscription:YES];
+    [device unitTestInjectAttributeReport:[self _testAttributeReportWithValue:currentTestValue++] fromSubscription:YES];
 
     usleep((useconds_t) (baseTestDelayTime * frequentReportMultiplier * USEC_PER_SEC));
-    [device unitTestInjectAttributeReport:[self testAttributeReportWithValue:currentTestValue++] fromSubscription:YES];
+    [device unitTestInjectAttributeReport:[self _testAttributeReportWithValue:currentTestValue++] fromSubscription:YES];
 
     usleep((useconds_t) (baseTestDelayTime * frequentReportMultiplier * USEC_PER_SEC));
-    [device unitTestInjectAttributeReport:[self testAttributeReportWithValue:currentTestValue++] fromSubscription:YES];
+    [device unitTestInjectAttributeReport:[self _testAttributeReportWithValue:currentTestValue++] fromSubscription:YES];
 
     // At this point, the threshold for reportToPersistenceDelayTimeMax should have hit, and persistence
     // should have happened with timer running down to persist again with the 5th report above. Need to
@@ -3817,7 +3835,7 @@ - (void)test036_TestStorageBehaviorConfiguration
     ]]];
 
     // Inject final report that makes MTRDevice recalculate delay with multiplier
-    [device unitTestInjectAttributeReport:[self testAttributeReportWithValue:currentTestValue++] fromSubscription:YES];
+    [device unitTestInjectAttributeReport:[self _testAttributeReportWithValue:currentTestValue++] fromSubscription:YES];
 
     [self waitForExpectations:@[ dataPersisted3 ] timeout:60];
 
@@ -3856,13 +3874,13 @@ - (void)test036_TestStorageBehaviorConfiguration
     ]]];
 
     // Inject report that makes MTRDevice detect the device is reporting excessively
-    [device unitTestInjectAttributeReport:[self testAttributeReportWithValue:currentTestValue++] fromSubscription:YES];
+    [device unitTestInjectAttributeReport:[self _testAttributeReportWithValue:currentTestValue++] fromSubscription:YES];
 
     // Now keep reporting excessively for base delay time max times max multiplier, plus a bit more
     NSDate * excessiveStartTime = [NSDate now];
     for (;;) {
         usleep((useconds_t) (baseTestDelayTime * 0.1 * USEC_PER_SEC));
-        [device unitTestInjectAttributeReport:[self testAttributeReportWithValue:currentTestValue++] fromSubscription:YES];
+        [device unitTestInjectAttributeReport:[self _testAttributeReportWithValue:currentTestValue++] fromSubscription:YES];
         NSTimeInterval elapsed = -[excessiveStartTime timeIntervalSinceNow];
         if (elapsed > (baseTestDelayTime * 2 * 5 * 1.2)) {
             break;
@@ -3879,7 +3897,7 @@ - (void)test036_TestStorageBehaviorConfiguration
 
     // And inject a report to trigger MTRDevice to recalculate that this device is no longer
     // reporting excessively
-    [device unitTestInjectAttributeReport:[self testAttributeReportWithValue:currentTestValue++] fromSubscription:YES];
+    [device unitTestInjectAttributeReport:[self _testAttributeReportWithValue:currentTestValue++] fromSubscription:YES];
 
     [self waitForExpectations:@[ dataPersisted4 ] timeout:60];
 

src/darwin/Framework/CHIPTests/MTRPerControllerStorageTests.m

@@ -1436,29 +1436,29 @@ - (void)doDataStoreMTRDeviceTestWithStorageDelegate:(id<MTRDeviceControllerStora
     __auto_type * delegate = [[MTRDeviceTestDelegate alloc] init];
 
     XCTestExpectation * subscriptionExpectation = [self expectationWithDescription:@"Subscription has been set up"];
-    XCTestExpectation * gotClusterDataPersisted = nil;
-    if (!disableStorageBehaviorOptimization) {
-        gotClusterDataPersisted = [self expectationWithDescription:@"Cluster data persisted"];
-    }
 
     delegate.onReportEnd = ^{
         [subscriptionExpectation fulfill];
     };
-    delegate.onClusterDataPersisted = ^{
-        [gotClusterDataPersisted fulfill];
+
+    __block BOOL onDeviceCachePrimedCalled = NO;
+    delegate.onDeviceCachePrimed = ^{
+        onDeviceCachePrimedCalled = YES;
     };
 
     // Verify that initially (before we have ever subscribed while using this
     // datastore) the device has no estimate for subscription latency.
     XCTAssertNil(device.estimatedSubscriptionLatency);
 
+    // And that the device cache is not primed.
+    XCTAssertFalse(device.deviceCachePrimed);
+
     [device setDelegate:delegate queue:queue];
 
     [self waitForExpectations:@[ subscriptionExpectation ] timeout:60];
 
-    if (!disableStorageBehaviorOptimization) {
-        [self waitForExpectations:@[ gotClusterDataPersisted ] timeout:60];
-    }
+    XCTAssertTrue(device.deviceCachePrimed);
+    XCTAssertTrue(onDeviceCachePrimedCalled);
 
     NSUInteger dataStoreValuesCount = 0;
     NSDictionary<MTRClusterPath *, MTRDeviceClusterData *> * dataStoreClusterData = [controller.controllerDataStore getStoredClusterDataForNodeID:deviceID];
@@ -1497,6 +1497,9 @@ - (void)doDataStoreMTRDeviceTestWithStorageDelegate:(id<MTRDeviceControllerStora
     // Check that the new device has an estimated subscription latency.
     XCTAssertNotNil(device.estimatedSubscriptionLatency);
 
+    // And that it's already primed.
+    XCTAssertTrue(device.deviceCachePrimed);
+
     // Check that this estimate is positive, since subscribing must have taken
     // some time.
     XCTAssertGreaterThan(device.estimatedSubscriptionLatency.doubleValue, 0);
@@ -1517,6 +1520,11 @@ - (void)doDataStoreMTRDeviceTestWithStorageDelegate:(id<MTRDeviceControllerStora
         [newDeviceGotClusterDataPersisted fulfill];
     };
 
+    __block BOOL newOnDeviceCachePrimedCalled = NO;
+    newDelegate.onDeviceCachePrimed = ^{
+        newOnDeviceCachePrimedCalled = YES;
+    };
+
     [newDevice setDelegate:newDelegate queue:queue];
 
     [self waitForExpectations:@[ newDeviceSubscriptionExpectation ] timeout:60];
@@ -1525,6 +1533,8 @@ - (void)doDataStoreMTRDeviceTestWithStorageDelegate:(id<MTRDeviceControllerStora
     }
     newDelegate.onReportEnd = nil;
 
+    XCTAssertFalse(newOnDeviceCachePrimedCalled);
+
     // 1) MTRDevice actually gets some attributes reported more than once
     // 2) Some attributes do change on resubscribe
     //   * With all-clusts-app as of 2024-02-10, out of 1287 persisted attributes, still 450 attributes were reported with filter