Fix historical event detection in MTRDevice.

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.

Author: bzbarsky-apple

src/darwin/Framework/CHIP/MTRDevice.mm

@@ -140,21 +140,34 @@ 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
 // enum so it's easier to notice that they need to stay in sync.
 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<unsigned long>(lastState), static_cast<unsigned long>(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<MTRClusterPath *, MTRDeviceClusterData *> *)_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<MTRDevice *> * weakSelf = [MTRWeakReference weakReferenceWithObject:self];

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
@@ -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();
 
@@ -2634,11 +2679,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 +3011,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 +3071,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 +3202,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 +3296,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 +3522,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"];
 
-    // 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.
+    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"];
+
+    __auto_type * delegate = [[MTRDeviceTestDelegate alloc] init];
+    delegate.onReachable = ^() {
+        [secondSubscriptionExpectation fulfill];
+    };
+
+    __block unsigned eventReportsReceived = 0;
+    delegate.onEventDataReceived = ^(NSArray<NSDictionary<NSString *, id> *> * eventReport) {
+        eventReportsReceived += eventReport.count;
+        for (NSDictionary<NSString *, id> * 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