Skip to content

Commit

Permalink
Fix up guarantees around the "device cache primed" notification. (#33600
Browse files Browse the repository at this point in the history 
)

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.
  • Loading branch information
@bzbarsky-apple
bzbarsky-apple authored May 28, 2024
1 parent 22a9dc3 commit 6368d7d
Show file tree
Hide file tree
Showing 3 changed files with 82 additions and 82 deletions.
90 changes: 31 additions & 59 deletions src/darwin/Framework/CHIP/MTRDevice.mm
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -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]) {
Expand Down Expand Up @@ -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];
}
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -1480,6 +1474,13 @@ - (void)_scheduleClusterDataPersistence
return;
}

// If we have nothing stored at all yet, store directly, so we move into a
// primed state.
if (!_deviceCachePrimed) {
[self _persistClusterData];
return;
}

// Ensure there is an array to keep the most recent report times
if (!_mostRecentReportTimes) {
_mostRecentReportTimes = [NSMutableArray array];
Expand Down Expand Up @@ -1525,7 +1526,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;
}
Expand Down Expand Up @@ -1601,6 +1602,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;
Expand Down Expand Up @@ -3165,10 +3179,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
Expand Down Expand Up @@ -3218,7 +3231,7 @@ - (void)_storePersistedDeviceData
- (BOOL)deviceCachePrimed
{
std::lock_guard lock(_lock);
return [self _isCachePrimedWithInitialConfigurationData];
return _deviceCachePrimed;
}

// If value is non-nil, associate with expectedValueID
Expand Down Expand Up @@ -3395,47 +3408,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];
Expand Down
46 changes: 32 additions & 14 deletions src/darwin/Framework/CHIPTests/MTRDeviceTests.m
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)],
Expand All @@ -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) {
Expand All @@ -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
Expand All @@ -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];

Expand All @@ -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
Expand Down Expand Up @@ -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];

Expand Down Expand Up @@ -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;
Expand All @@ -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];

Expand Down
28 changes: 19 additions & 9 deletions src/darwin/Framework/CHIPTests/MTRPerControllerStorageTests.m
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1437,29 +1437,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];
Expand Down Expand Up @@ -1498,6 +1498,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);
Expand All @@ -1518,6 +1521,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];
Expand All @@ -1526,6 +1534,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
Expand Down

0 comments on commit 6368d7d

Please sign in to comment.