[Darwin] MTRDevice should change state to reachable immediately upon …

…receiving subscription reports (#28996)

* [Darwin] MTRDevice should change state to reachable immediately upon receiving subscription reports

* Fix unit tests

* Address review comment on _handleEventReport: needing to handle _state behavior change

Co-authored-by: Boris Zbarsky <bzbarsky@apple.com>

* Clarify _handleEventReport comments

* Clarify further _handleEventReport comments

---------

Co-authored-by: Boris Zbarsky <bzbarsky@apple.com>

src/darwin/Framework/CHIP/MTRBaseSubscriptionCallback.h

@@ -56,13 +56,16 @@ typedef void (^ErrorCallback)(NSError * error);
 typedef void (^SubscriptionEstablishedHandler)(void);
 typedef void (^OnDoneHandler)(void);
 typedef void (^UnsolicitedMessageFromPublisherHandler)(void);
+typedef void (^ReportBeginHandler)(void);
+typedef void (^ReportEndHandler)(void);
 
 class MTRBaseSubscriptionCallback : public chip::app::ClusterStateCache::Callback {
 public:
     MTRBaseSubscriptionCallback(DataReportCallback attributeReportCallback, DataReportCallback eventReportCallback,
         ErrorCallback errorCallback, MTRDeviceResubscriptionScheduledHandler _Nullable resubscriptionCallback,
         SubscriptionEstablishedHandler _Nullable subscriptionEstablishedHandler, OnDoneHandler _Nullable onDoneHandler,
-        UnsolicitedMessageFromPublisherHandler _Nullable unsolicitedMessageFromPublisherHandler = NULL)
+        UnsolicitedMessageFromPublisherHandler _Nullable unsolicitedMessageFromPublisherHandler = nil,
+        ReportBeginHandler _Nullable reportBeginHandler = nil, ReportEndHandler _Nullable reportEndHandler = nil)
         : mAttributeReportCallback(attributeReportCallback)
         , mEventReportCallback(eventReportCallback)
         , mErrorCallback(errorCallback)
@@ -71,6 +74,8 @@ class MTRBaseSubscriptionCallback : public chip::app::ClusterStateCache::Callbac
         , mBufferedReadAdapter(*this)
         , mOnDoneHandler(onDoneHandler)
         , mUnsolicitedMessageFromPublisherHandler(unsolicitedMessageFromPublisherHandler)
+        , mReportBeginHandler(reportBeginHandler)
+        , mReportEndHandler(reportEndHandler)
     {
     }
 
@@ -137,6 +142,8 @@ class MTRBaseSubscriptionCallback : public chip::app::ClusterStateCache::Callbac
     MTRDeviceResubscriptionScheduledHandler _Nullable mResubscriptionCallback = nil;
     SubscriptionEstablishedHandler _Nullable mSubscriptionEstablishedHandler = nil;
     UnsolicitedMessageFromPublisherHandler _Nullable mUnsolicitedMessageFromPublisherHandler = nil;
+    ReportBeginHandler _Nullable mReportBeginHandler = nil;
+    ReportEndHandler _Nullable mReportEndHandler = nil;
     chip::app::BufferedReadCallback mBufferedReadAdapter;
 
     // Our lifetime management is a little complicated.  On errors that don't

src/darwin/Framework/CHIP/MTRBaseSubscriptionCallback.mm

@@ -27,6 +27,9 @@
 {
     mAttributeReports = [NSMutableArray new];
     mEventReports = [NSMutableArray new];
+    if (mReportBeginHandler) {
+        mReportBeginHandler();
+    }
 }
 
 // Reports attribute and event data if any exists
@@ -48,7 +51,13 @@
     }
 }
 
-void MTRBaseSubscriptionCallback::OnReportEnd() { ReportData(); }
+void MTRBaseSubscriptionCallback::OnReportEnd()
+{
+    ReportData();
+    if (mReportEndHandler) {
+        mReportEndHandler();
+    }
+}
 
 void MTRBaseSubscriptionCallback::OnError(CHIP_ERROR aError)
 {

src/darwin/Framework/CHIP/MTRDevice.mm

@@ -91,16 +91,20 @@ - (id)strongObject
 using namespace chip::app;
 using namespace chip::Protocols::InteractionModel;
 
+typedef void (^FirstReportHandler)(void);
+
 namespace {
 
 class SubscriptionCallback final : public MTRBaseSubscriptionCallback {
 public:
     SubscriptionCallback(DataReportCallback attributeReportCallback, DataReportCallback eventReportCallback,
         ErrorCallback errorCallback, MTRDeviceResubscriptionScheduledHandler resubscriptionCallback,
         SubscriptionEstablishedHandler subscriptionEstablishedHandler, OnDoneHandler onDoneHandler,
-        UnsolicitedMessageFromPublisherHandler unsolicitedMessageFromPublisherHandler)
+        UnsolicitedMessageFromPublisherHandler unsolicitedMessageFromPublisherHandler, ReportBeginHandler reportBeginHandler,
+        ReportEndHandler reportEndHandler)
         : MTRBaseSubscriptionCallback(attributeReportCallback, eventReportCallback, errorCallback, resubscriptionCallback,
-            subscriptionEstablishedHandler, onDoneHandler, unsolicitedMessageFromPublisherHandler)
+            subscriptionEstablishedHandler, onDoneHandler, unsolicitedMessageFromPublisherHandler, reportBeginHandler,
+            reportEndHandler)
     {
     }
 
@@ -278,7 +282,6 @@ - (void)nodeMayBeAdvertisingOperational
 // Return YES if there's a valid delegate AND subscription is expected to report value
 - (BOOL)_subscriptionAbleToReport
 {
-    // TODO: include period from when first report comes in until establish callback
     return (_weakDelegate.strongObject) && (_state == MTRDeviceStateReachable);
 }
 
@@ -290,9 +293,11 @@ - (void)_changeState:(MTRDeviceState)state
     _state = state;
     if (lastState != state) {
         if (state != MTRDeviceStateReachable) {
-            MTR_LOG_INFO("%@ Set estimated start time to nil due to state change", self);
+            MTR_LOG_INFO("%@ State change %lu => %lu, set estimated start time to nil", self, lastState, state);
             _estimatedStartTime = nil;
             _estimatedStartTimeFromGeneralDiagnosticsUpTime = nil;
+        } else {
+            MTR_LOG_INFO("%@ State change %lu => %lu", self, lastState, state);
         }
         id<MTRDeviceDelegate> delegate = _weakDelegate.strongObject;
         if (delegate) {
@@ -411,6 +416,20 @@ - (void)_handleUnsolicitedMessageFromPublisher
     os_unfair_lock_unlock(&self->_lock);
 }
 
+- (void)_handleReportBegin
+{
+    os_unfair_lock_lock(&self->_lock);
+    [self _changeState:MTRDeviceStateReachable];
+    os_unfair_lock_unlock(&self->_lock);
+}
+
+- (void)_handleReportEnd
+{
+    os_unfair_lock_lock(&self->_lock);
+    _estimatedStartTimeFromGeneralDiagnosticsUpTime = nil;
+    os_unfair_lock_unlock(&self->_lock);
+}
+
 // assume lock is held
 - (void)_reportAttributes:(NSArray<NSDictionary<NSString *, id> *> *)attributes
 {
@@ -442,11 +461,33 @@ - (void)_handleEventReport:(NSArray<NSDictionary<NSString *, id> *> *)eventRepor
     NSDate * oldEstimatedStartTime = _estimatedStartTime;
     for (NSDictionary<NSString *, id> * eventDict in eventReport) {
         // Whenever a StartUp event is received, reset the estimated start time
+        //   New subscription case
+        //     - Starts Unreachable
+        //     - Start CASE and send subscription request
+        //     - Receive priming report ReportBegin
+        //     - Optionally receive UpTime attribute - update time and save start time estimate
+        //     - Optionally receive StartUp event
+        //       - Set estimated system time from event receipt time, or saved UpTime estimate if exists
+        //     - ReportEnd handler clears the saved start time estimate based on UpTime
+        //   Subscription dropped from client point of view case
+        //     - Starts Unreachable
+        //     - Resubscribe happens after some time, and then same as the above
+        //   Server resuming subscription after reboot case
+        //     - Starts Reachable
+        //     - Receive priming report ReportBegin
+        //     - Optionally receive UpTime attribute - update time and save value
+        //     - Optionally receive StartUp event
+        //       - Set estimated system time from event receipt time, or saved UpTime estimate if exists
+        //     - ReportEnd handler clears the saved start time estimate based on UpTime
+        //   Server resuming subscription after timeout case
+        //     - Starts Reachable
+        //     - Receive priming report ReportBegin
+        //     - Optionally receive UpTime attribute - update time and save value
+        //     - ReportEnd handler clears the saved start time estimate based on UpTime
         MTREventPath * eventPath = eventDict[MTREventPathKey];
         BOOL isStartUpEvent = (eventPath.cluster.unsignedLongValue == MTRClusterIDTypeBasicInformationID)
             && (eventPath.event.unsignedLongValue == MTREventIDTypeClusterBasicInformationEventStartUpID);
-        if (isStartUpEvent && (_state == MTRDeviceStateReachable)) {
-            // StartUp event received when server resumes subscription
+        if (isStartUpEvent) {
             if (_estimatedStartTimeFromGeneralDiagnosticsUpTime) {
                 // If UpTime was received, make use of it as mark of system start time
                 MTR_LOG_INFO("%@ StartUp event: set estimated start time forward to %@", self,
@@ -610,6 +651,18 @@ - (void)_setupSubscription
                                // OnUnsolicitedMessageFromPublisher
                                [self _handleUnsolicitedMessageFromPublisher];
                            });
+                       },
+                       ^(void) {
+                           MTR_LOG_DEFAULT("%@ got report begin", self);
+                           dispatch_async(self.queue, ^{
+                               [self _handleReportBegin];
+                           });
+                       },
+                       ^(void) {
+                           MTR_LOG_DEFAULT("%@ got report end", self);
+                           dispatch_async(self.queue, ^{
+                               [self _handleReportEnd];
+                           });
                        });
 
                    // Set up a cluster state cache.  We just want this for the logic it has for

src/darwin/Framework/CHIPTests/MTRDeviceTests.m

@@ -118,19 +118,19 @@ - (void)controller:(MTRDeviceController *)controller commissioningComplete:(NSEr
 typedef void (^MTRDeviceTestDelegateDataHandler)(NSArray<NSDictionary<NSString *, id> *> *);
 
 @interface MTRDeviceTestDelegate : NSObject <MTRDeviceDelegate>
-@property (nonatomic) dispatch_block_t onSubscriptionEstablished;
+@property (nonatomic) dispatch_block_t onReachable;
+@property (nonatomic, nullable) dispatch_block_t onNotReachable;
 @property (nonatomic, nullable) MTRDeviceTestDelegateDataHandler onAttributeDataReceived;
 @property (nonatomic, nullable) MTRDeviceTestDelegateDataHandler onEventDataReceived;
-@property (nonatomic, nullable) dispatch_block_t onSubscriptionDropped;
 @end
 
 @implementation MTRDeviceTestDelegate
 - (void)device:(MTRDevice *)device stateChanged:(MTRDeviceState)state
 {
     if (state == MTRDeviceStateReachable) {
-        self.onSubscriptionEstablished();
-    } else if (state == MTRDeviceStateUnknown && self.onSubscriptionDropped != nil) {
-        self.onSubscriptionDropped();
+        self.onReachable();
+    } else if (state != MTRDeviceStateReachable && self.onNotReachable != nil) {
+        self.onNotReachable();
     }
 }
 
@@ -1423,10 +1423,12 @@ - (void)test017_TestMTRDeviceBasics
     __auto_type * device = [MTRDevice deviceWithNodeID:kDeviceId deviceController:sController];
     dispatch_queue_t queue = dispatch_get_main_queue();
 
+    // Given reachable state becomes true before underlying OnSubscriptionEstablished callback, this expectation is necessary but
+    // not sufficient as a mark to the end of reports
     XCTestExpectation * subscriptionExpectation = [self expectationWithDescription:@"Subscription has been set up"];
 
     __auto_type * delegate = [[MTRDeviceTestDelegate alloc] init];
-    delegate.onSubscriptionEstablished = ^() {
+    delegate.onReachable = ^() {
         [subscriptionExpectation fulfill];
     };
 
@@ -1435,6 +1437,10 @@ - (void)test017_TestMTRDeviceBasics
         attributeReportsReceived += data.count;
     };
 
+    // This is dependent on current implementation that priming reports send attributes and events in that order, and also that
+    // events in this test would fit in one report. So receiving events would mean all attributes and events have been received, and
+    // can satisfy the test below.
+    XCTestExpectation * gotReportsExpectation = [self expectationWithDescription:@"Attribute and Event reports have been received"];
     __block unsigned eventReportsReceived = 0;
     delegate.onEventDataReceived = ^(NSArray<NSDictionary<NSString *, id> *> * eventReport) {
         eventReportsReceived += eventReport.count;
@@ -1451,6 +1457,7 @@ - (void)test017_TestMTRDeviceBasics
                 XCTAssertNotNil(eventDict[MTREventTimestampDateKey]);
             }
         }
+        [gotReportsExpectation fulfill];
     };
 
     [device setDelegate:delegate queue:queue];
@@ -1481,24 +1488,14 @@ - (void)test017_TestMTRDeviceBasics
     [device readAttributeWithEndpointID:@(1) clusterID:@(MTRClusterIDTypeLevelControlID) attributeID:@(4) params:nil];
     [device readAttributeWithEndpointID:@(1) clusterID:@(MTRClusterIDTypeLevelControlID) attributeID:@(4) params:nil];
 
-    [self waitForExpectations:@[ subscriptionExpectation ] timeout:60];
+    [self waitForExpectations:@[ subscriptionExpectation, gotReportsExpectation ] timeout:60];
 
     XCTAssertNotEqual(attributeReportsReceived, 0);
     XCTAssertNotEqual(eventReportsReceived, 0);
 
     attributeReportsReceived = 0;
     eventReportsReceived = 0;
 
-    XCTestExpectation * resubscriptionExpectation = [self expectationWithDescription:@"Resubscription has happened"];
-    delegate.onSubscriptionEstablished = ^() {
-        [resubscriptionExpectation fulfill];
-    };
-
-    XCTestExpectation * subscriptionDroppedExpectation = [self expectationWithDescription:@"Subscription has dropped"];
-    delegate.onSubscriptionDropped = ^() {
-        [subscriptionDroppedExpectation fulfill];
-    };
-
     // Before resubscribe, first test write failure and expected value effects
     NSNumber * testEndpointID = @(1);
     NSNumber * testClusterID = @(8);
@@ -1547,11 +1544,25 @@ - (void)test017_TestMTRDeviceBasics
     [device readAttributeWithEndpointID:testEndpointID clusterID:testClusterID attributeID:testAttributeID params:nil];
     [self waitForExpectations:@[ attributeReportErrorExpectation ] timeout:10];
 
+    // Resubscription test setup
+    XCTestExpectation * subscriptionDroppedExpectation = [self expectationWithDescription:@"Subscription has dropped"];
+    delegate.onNotReachable = ^() {
+        [subscriptionDroppedExpectation fulfill];
+    };
+    XCTestExpectation * resubscriptionExpectation = [self expectationWithDescription:@"Resubscription has happened"];
+    delegate.onReachable = ^() {
+        [resubscriptionExpectation fulfill];
+    };
+
     // reset the onAttributeDataReceived to validate the following resubscribe test
     delegate.onAttributeDataReceived = ^(NSArray<NSDictionary<NSString *, id> *> * data) {
         attributeReportsReceived += data.count;
     };
 
+    delegate.onEventDataReceived = ^(NSArray<NSDictionary<NSString *, id> *> * eventReport) {
+        eventReportsReceived += eventReport.count;
+    };
+
     // Now trigger another subscription which will cause ours to drop; we should re-subscribe after that.
     MTRBaseDevice * baseDevice = GetConnectedDevice();
     __auto_type params = [[MTRSubscribeParams alloc] initWithMinInterval:@(1) maxInterval:@(10)];
@@ -1580,9 +1591,9 @@ - (void)test017_TestMTRDeviceBasics
 
     // Now make sure we ignore later tests.  Ideally we would just unsubscribe
     // or remove the delegate, but there's no good way to do that.
-    delegate.onSubscriptionEstablished = ^() {
+    delegate.onReachable = ^() {
     };
-    delegate.onSubscriptionDropped = nil;
+    delegate.onNotReachable = nil;
     delegate.onAttributeDataReceived = nil;
     delegate.onEventDataReceived = nil;