From 105661033ebd645b22acce5c87f21e8bb0102b4c Mon Sep 17 00:00:00 2001 From: Boris Zbarsky Date: Wed, 15 May 2024 20:11:44 -0400 Subject: [PATCH] Fix historical event detection in MTRDevice. (#33462) A few fixes here: * Fix MTRDeviceTests to clean up MTRDevice between tests, so each test starts with a known clean slate. * Fix the "are we getting a priming report?" detection in MTRDevice. Relying on reachability state is not correct, because unsolicited reports can mark us reachable even while we are in the middle of a priming report. --- src/darwin/Framework/CHIP/MTRDevice.mm | 45 +++- .../Framework/CHIPTests/MTRDeviceTests.m | 201 ++++++++++++++---- 2 files changed, 193 insertions(+), 53 deletions(-) diff --git a/src/darwin/Framework/CHIP/MTRDevice.mm b/src/darwin/Framework/CHIP/MTRDevice.mm index 0183b41797516b..5181b6ca5fdbfc 100644 --- a/src/darwin/Framework/CHIP/MTRDevice.mm +++ b/src/darwin/Framework/CHIP/MTRDevice.mm @@ -140,7 +140,15 @@ typedef NS_ENUM(NSUInteger, MTRInternalDeviceState) { // InitialSubscriptionEstablished means we have at some point finished setting up a // subscription. That subscription may have dropped since then, but if so it's the ReadClient's // responsibility to re-establish it. - MTRInternalDeviceStateInitalSubscriptionEstablished = 2, + MTRInternalDeviceStateInitialSubscriptionEstablished = 2, + // Resubscribing means we had established a subscription, but then + // detected a subscription drop due to not receiving a report on time. This + // covers all the actions that happen when re-subscribing (discovery, CASE, + // getting priming reports, etc). + MTRInternalDeviceStateResubscribing = 3, + // LaterSubscriptionEstablished meant that we had a subscription drop and + // then re-created a subscription. + MTRInternalDeviceStateLaterSubscriptionEstablished = 4, }; // Utility methods for working with MTRInternalDeviceState, located near the @@ -148,13 +156,18 @@ typedef NS_ENUM(NSUInteger, MTRInternalDeviceState) { namespace { bool HadSubscriptionEstablishedOnce(MTRInternalDeviceState state) { - return state >= MTRInternalDeviceStateInitalSubscriptionEstablished; + return state >= MTRInternalDeviceStateInitialSubscriptionEstablished; } bool NeedToStartSubscriptionSetup(MTRInternalDeviceState state) { return state <= MTRInternalDeviceStateUnsubscribed; } + +bool HaveSubscriptionEstablishedRightNow(MTRInternalDeviceState state) +{ + return state == MTRInternalDeviceStateInitialSubscriptionEstablished || state == MTRInternalDeviceStateLaterSubscriptionEstablished; +} } // anonymous namespace typedef NS_ENUM(NSUInteger, MTRDeviceExpectedValueFieldIndex) { @@ -878,6 +891,16 @@ - (void)_changeState:(MTRDeviceState)state } } +- (void)_changeInternalState:(MTRInternalDeviceState)state +{ + os_unfair_lock_assert_owner(&self->_lock); + MTRInternalDeviceState lastState = _internalDeviceState; + _internalDeviceState = state; + if (lastState != state) { + MTR_LOG_DEFAULT("%@ internal state change %lu => %lu", self, static_cast(lastState), static_cast(state)); + } +} + // First Time Sync happens 2 minutes after reachability (this can be changed in the future) #define MTR_DEVICE_TIME_UPDATE_INITIAL_WAIT_TIME_SEC (60 * 2) - (void)_handleSubscriptionEstablished @@ -886,7 +909,11 @@ - (void)_handleSubscriptionEstablished // reset subscription attempt wait time when subscription succeeds _lastSubscriptionAttemptWait = 0; - _internalDeviceState = MTRInternalDeviceStateInitalSubscriptionEstablished; + if (HadSubscriptionEstablishedOnce(_internalDeviceState)) { + [self _changeInternalState:MTRInternalDeviceStateLaterSubscriptionEstablished]; + } else { + [self _changeInternalState:MTRInternalDeviceStateInitialSubscriptionEstablished]; + } // As subscription is established, check if the delegate needs to be informed if (!_delegateDeviceCachePrimedCalled) { @@ -913,7 +940,7 @@ - (void)_handleSubscriptionError:(NSError *)error { std::lock_guard lock(_lock); - _internalDeviceState = MTRInternalDeviceStateUnsubscribed; + [self _changeInternalState:MTRInternalDeviceStateUnsubscribed]; _unreportedEvents = nil; [self _changeState:MTRDeviceStateUnreachable]; @@ -924,6 +951,7 @@ - (void)_handleResubscriptionNeeded std::lock_guard lock(_lock); [self _changeState:MTRDeviceStateUnknown]; + [self _changeInternalState:MTRInternalDeviceStateResubscribing]; // If we are here, then the ReadClient either just detected a subscription // drop or just tried again and failed. Either way, count it as "tried and @@ -1044,11 +1072,12 @@ - (void)_handleReportBegin _receivingReport = YES; if (_state != MTRDeviceStateReachable) { - _receivingPrimingReport = YES; [self _changeState:MTRDeviceStateReachable]; - } else { - _receivingPrimingReport = NO; } + + // If we currently don't have an established subscription, this must be a + // priming report. + _receivingPrimingReport = !HaveSubscriptionEstablishedRightNow(_internalDeviceState); } - (NSDictionary *)_clusterDataToPersistSnapshot @@ -1461,7 +1490,7 @@ - (void)_setupSubscription return; } - _internalDeviceState = MTRInternalDeviceStateSubscribing; + [self _changeInternalState:MTRInternalDeviceStateSubscribing]; // Set up a timer to mark as not reachable if it takes too long to set up a subscription MTRWeakReference * weakSelf = [MTRWeakReference weakReferenceWithObject:self]; diff --git a/src/darwin/Framework/CHIPTests/MTRDeviceTests.m b/src/darwin/Framework/CHIPTests/MTRDeviceTests.m index 0b198bcbbc8bdf..c05ee000b20e5f 100644 --- a/src/darwin/Framework/CHIPTests/MTRDeviceTests.m +++ b/src/darwin/Framework/CHIPTests/MTRDeviceTests.m @@ -218,6 +218,56 @@ - (void)setUp { [super setUp]; [self setContinueAfterFailure:NO]; + + // Ensure the test starts with clean slate in terms of stored data. + if (sController != nil) { + [sController.controllerDataStore clearAllStoredClusterData]; + NSDictionary * storedClusterDataAfterClear = [sController.controllerDataStore getStoredClusterDataForNodeID:@(kDeviceId)]; + XCTAssertEqual(storedClusterDataAfterClear.count, 0); + } +} + +- (void)tearDown +{ + // Make sure our MTRDevice instances, which are stateful, do not keep that + // state between different tests. + if (sController != nil) { + __auto_type * device = [MTRDevice deviceWithNodeID:@(kDeviceId) controller:sController]; + [sController removeDevice:device]; + } + + // Try to make sure we don't have any outstanding subscriptions from + // previous tests, by sending a subscribe request that will get rid of + // existing subscriptions and then fail out due to requesting a subscribe to + // a nonexistent cluster. + if (mConnectedDevice != nil) { + dispatch_queue_t queue = dispatch_get_main_queue(); + + MTRSubscribeParams * params = [[MTRSubscribeParams alloc] initWithMinInterval:@(0) maxInterval:@(10)]; + params.resubscribeAutomatically = NO; + params.replaceExistingSubscriptions = YES; + + XCTestExpectation * errorExpectation = [self expectationWithDescription:@"Canceled all subscriptions"]; + + // There should be no Basic Information cluster on random endpoints. + [mConnectedDevice subscribeToAttributesWithEndpointID:@10000 + clusterID:@(MTRClusterIDTypeBasicInformationID) + attributeID:@(0) + params:params + queue:queue + reportHandler:^(id _Nullable values, NSError * _Nullable error) { + XCTAssertNil(values); + XCTAssertNotNil(error); + [errorExpectation fulfill]; + } + subscriptionEstablished:^() { + XCTFail("Did not expect subscription to Basic Information on random endpoint to succeed"); + }]; + + [self waitForExpectations:@[ errorExpectation ] timeout:kTimeoutInSeconds]; + } + + [super tearDown]; } - (void)test001_ReadAttribute @@ -406,6 +456,7 @@ - (void)test005_Subscribe // Subscribe XCTestExpectation * expectation = [self expectationWithDescription:@"subscribe OnOff attribute"]; __auto_type * params = [[MTRSubscribeParams alloc] initWithMinInterval:@(1) maxInterval:@(10)]; + params.resubscribeAutomatically = NO; [device subscribeToAttributesWithEndpointID:@1 clusterID:@6 attributeID:@0 @@ -1278,8 +1329,7 @@ - (void)test015_FailedSubscribeWithQueueAcrossShutdown __auto_type clusterStateCacheContainer = [[MTRAttributeCacheContainer alloc] init]; __auto_type * params = [[MTRSubscribeParams alloc] init]; params.resubscribeAutomatically = NO; - params.replaceExistingSubscriptions = NO; // Not strictly needed, but checking that doing this does not - // affect this subscription erroring out correctly. + params.replaceExistingSubscriptions = NO; // Not strictly needed, but checking that doing this does not affect this subscription erroring out correctly. [device subscribeWithQueue:queue minInterval:1 maxInterval:2 @@ -1387,11 +1437,6 @@ - (void)test016_FailedSubscribeWithCacheReadDuringFailure - (void)test017_TestMTRDeviceBasics { - // Ensure the test starts with clean slate, even with MTRDeviceControllerLocalTestStorage enabled - [sController.controllerDataStore clearAllStoredClusterData]; - NSDictionary * storedClusterDataAfterClear = [sController.controllerDataStore getStoredClusterDataForNodeID:@(kDeviceId)]; - XCTAssertEqual(storedClusterDataAfterClear.count, 0); - __auto_type * device = [MTRDevice deviceWithNodeID:kDeviceId deviceController:sController]; dispatch_queue_t queue = dispatch_get_main_queue(); @@ -2149,6 +2194,7 @@ - (void)test023_SubscribeMultipleAttributes // Subscribe XCTestExpectation * expectation = [self expectationWithDescription:@"subscribe OnOff attribute"]; __auto_type * params = [[MTRSubscribeParams alloc] initWithMinInterval:@(1) maxInterval:@(10)]; + params.resubscribeAutomatically = NO; NSNumber * failClusterId = @5678; NSNumber * failEndpointId = @1000; @@ -2406,6 +2452,7 @@ - (void)test025_SubscribeMultipleEvents // Subscribe XCTestExpectation * expectation = [self expectationWithDescription:@"subscribe multiple events"]; __auto_type * params = [[MTRSubscribeParams alloc] initWithMinInterval:@(1) maxInterval:@(10)]; + params.resubscribeAutomatically = NO; NSArray * eventPaths = @[ // Startup event. @@ -2415,7 +2462,7 @@ - (void)test025_SubscribeMultipleEvents ]; XCTestExpectation * startupEventExpectation = [self expectationWithDescription:@"report startup event"]; - __auto_type reportHandler = ^(id _Nullable values, NSError * _Nullable error) { + __block __auto_type reportHandler = ^(id _Nullable values, NSError * _Nullable error) { XCTAssertNil(error); XCTAssertTrue([values isKindOfClass:[NSArray class]]); @@ -2455,18 +2502,26 @@ - (void)test025_SubscribeMultipleEvents }; [device subscribeToAttributePaths:nil - eventPaths:eventPaths - params:params - queue:queue - reportHandler:reportHandler - subscriptionEstablished:^{ - NSLog(@"subscribe complete"); - [expectation fulfill]; - } - resubscriptionScheduled:nil]; + eventPaths:eventPaths + params:params + queue:queue + reportHandler:^(id _Nullable values, NSError * _Nullable error) { + if (reportHandler != nil) { + reportHandler(values, error); + } + } + subscriptionEstablished:^{ + NSLog(@"subscribe complete"); + [expectation fulfill]; + } + resubscriptionScheduled:nil]; // Wait till establishment [self waitForExpectations:@[ startupEventExpectation, expectation ] timeout:kTimeoutInSeconds]; + + // Null out reportHandler, so we don't notify it when the + // subscription tears down. + reportHandler = nil; } - (void)test026_LocationAttribute @@ -2634,11 +2689,6 @@ - (void)test028_TimeZoneAndDST - (void)test029_MTRDeviceWriteCoalescing { - // Ensure the test starts with clean slate, even with MTRDeviceControllerLocalTestStorage enabled - [sController.controllerDataStore clearAllStoredClusterData]; - NSDictionary * storedClusterDataAfterClear = [sController.controllerDataStore getStoredClusterDataForNodeID:@(kDeviceId)]; - XCTAssertEqual(storedClusterDataAfterClear.count, 0); - __auto_type * device = [MTRDevice deviceWithNodeID:kDeviceId deviceController:sController]; dispatch_queue_t queue = dispatch_get_main_queue(); @@ -2971,15 +3021,8 @@ - (void)test031_MTRDeviceAttributeCacheLocalTestStorage { dispatch_queue_t queue = dispatch_get_main_queue(); - // First start with clean slate by removing the MTRDevice and clearing the persisted cache + // Get the subscription primed __auto_type * device = [MTRDevice deviceWithNodeID:@(kDeviceId) controller:sController]; - [sController removeDevice:device]; - [sController.controllerDataStore clearAllStoredClusterData]; - NSDictionary * storedClusterDataAfterClear = [sController.controllerDataStore getStoredClusterDataForNodeID:@(kDeviceId)]; - XCTAssertEqual(storedClusterDataAfterClear.count, 0); - - // Now recreate device and get subscription primed - device = [MTRDevice deviceWithNodeID:@(kDeviceId) controller:sController]; XCTestExpectation * gotReportsExpectation = [self expectationWithDescription:@"Attribute and Event reports have been received"]; XCTestExpectation * gotDeviceCachePrimed = [self expectationWithDescription:@"Device cache primed for the first time"]; __auto_type * delegate = [[MTRDeviceTestDelegate alloc] init]; @@ -3038,12 +3081,6 @@ - (void)test031_MTRDeviceAttributeCacheLocalTestStorage } NSUInteger storedAttributeCountDifferenceFromMTRDeviceReport = dataStoreAttributeCountAfterSecondSubscription - attributesReportedWithSecondSubscription; XCTAssertTrue(storedAttributeCountDifferenceFromMTRDeviceReport > 300); - - // We need to remove the device here since the MTRDevice retains its reachable state. So if the next test needs to start with a clean state, - // it can't do that since the MTRDevice becomes reachable in the previous test. Since there are no changes detected in reachability, - // the onReachable callback to the delegate is not called. - // TODO: #33205 Ensure we have a clean slate w.r.t MTRDevice before running each test. - [sController removeDevice:device]; } - (void)test032_MTRPathClassesEncoding @@ -3175,11 +3212,6 @@ + (void)checkAttributeReportTriggersConfigurationChanged:(MTRAttributeIDType)att - (void)test033_TestMTRDeviceDeviceConfigurationChanged { - // Ensure the test starts with clean slate. - [sController.controllerDataStore clearAllStoredClusterData]; - NSDictionary * storedClusterDataAfterClear = [sController.controllerDataStore getStoredClusterDataForNodeID:@(kDeviceId)]; - XCTAssertEqual(storedClusterDataAfterClear.count, 0); - __auto_type * device = [MTRDevice deviceWithNodeID:kDeviceId deviceController:sController]; dispatch_queue_t queue = dispatch_get_main_queue(); @@ -3274,7 +3306,7 @@ - (void)test033_TestMTRDeviceDeviceConfigurationChanged [device setDelegate:delegate queue:queue]; - // Wait for subscription set up and intitial reports received. + // Wait for subscription set up and initial reports received. [self waitForExpectations:@[ subscriptionExpectation, gotInitialReportsExpectation, @@ -3500,11 +3532,90 @@ - (void)test033_TestMTRDeviceDeviceConfigurationChanged [device unitTestInjectAttributeReport:attributeReport]; [self waitForExpectations:@[ gotAttributeReportWithMultipleAttributesExpectation, gotAttributeReportWithMultipleAttributesEndExpectation, deviceConfigurationChangedExpectationForAttributeReportWithMultipleAttributes ] timeout:kTimeoutInSeconds]; +} + +- (void)test034_TestMTRDeviceHistoricalEvents +{ + dispatch_queue_t queue = dispatch_get_main_queue(); + + NSDictionary * storedClusterDataAfterClear = [sController.controllerDataStore getStoredClusterDataForNodeID:@(kDeviceId)]; + XCTAssertEqual(storedClusterDataAfterClear.count, 0); + + // Set up a subscription via mConnectedDevice that will send us continuous + // reports. + XCTestExpectation * firstSubscriptionExpectation = [self expectationWithDescription:@"First subscription established"]; + + MTRSubscribeParams * params = [[MTRSubscribeParams alloc] initWithMinInterval:@(0) maxInterval:@(0)]; + params.resubscribeAutomatically = NO; + + [mConnectedDevice subscribeToAttributesWithEndpointID:@(0) + clusterID:@(MTRClusterIDTypeBasicInformationID) + attributeID:@(0) + params:params + queue:queue + reportHandler:^(id _Nullable values, NSError * _Nullable error) { + } + subscriptionEstablished:^() { + [firstSubscriptionExpectation fulfill]; + }]; + + [self waitForExpectations:@[ firstSubscriptionExpectation ] timeout:kTimeoutInSeconds]; + + // Now set up our MTRDevice and do a subscribe. Make sure all the events we + // get are marked "historical". + __auto_type * device = [MTRDevice deviceWithNodeID:kDeviceId deviceController:sController]; + XCTestExpectation * secondSubscriptionExpectation = [self expectationWithDescription:@"Second subscription established"]; + XCTestExpectation * gotFirstReportsExpectation = [self expectationWithDescription:@"First Attribute and Event reports have been received"]; - // We need to remove the device here, because we injected data into its attribute cache - // that does not match the actual server. - // TODO: #33205 Ensure we have a clean slate w.r.t MTRDevice before running each test. + __auto_type * delegate = [[MTRDeviceTestDelegate alloc] init]; + delegate.onReachable = ^() { + [secondSubscriptionExpectation fulfill]; + }; + + __block unsigned eventReportsReceived = 0; + delegate.onEventDataReceived = ^(NSArray *> * eventReport) { + eventReportsReceived += eventReport.count; + for (NSDictionary * eventDict in eventReport) { + NSNumber * reportIsHistorical = eventDict[MTREventIsHistoricalKey]; + XCTAssertTrue(reportIsHistorical.boolValue); + } + }; + + delegate.onReportEnd = ^() { + [gotFirstReportsExpectation fulfill]; + }; + + [device setDelegate:delegate queue:queue]; + + [self waitForExpectations:@[ secondSubscriptionExpectation, gotFirstReportsExpectation ] timeout:60]; + + // Must have gotten some events (at least StartUp!) + XCTAssertTrue(eventReportsReceived > 0); + + // Remove the device, then try again, now with us having stored cluster + // data. All the events should still be reported as historical. [sController removeDevice:device]; + + eventReportsReceived = 0; + + device = [MTRDevice deviceWithNodeID:kDeviceId deviceController:sController]; + XCTestExpectation * thirdSubscriptionExpectation = [self expectationWithDescription:@"Third subscription established"]; + XCTestExpectation * gotSecondReportsExpectation = [self expectationWithDescription:@"Second Attribute and Event reports have been received"]; + + delegate.onReachable = ^() { + [thirdSubscriptionExpectation fulfill]; + }; + + delegate.onReportEnd = ^() { + [gotSecondReportsExpectation fulfill]; + }; + + [device setDelegate:delegate queue:queue]; + + [self waitForExpectations:@[ thirdSubscriptionExpectation, gotSecondReportsExpectation ] timeout:60]; + + // Must have gotten some events (at least StartUp!) + XCTAssertTrue(eventReportsReceived > 0); } @end