[Darwin] Ignore superseded MTRDevice subscription reattempt timers (#74704) * [Darwin] Ignore superseded MTRDevice subscription reattempt timers _doHandleSubscriptionReset schedules a reattempt with dispatch_after or the subscription pool, and the only way to cancel it is to clear reattemptingSubscription. If another trigger starts a subscription before the timer fires and that attempt fails too, the next reset sets the flag again and schedules a longer wait, but the earlier timer still fires and starts the reattempt at the earlier time, so the backoff is cut short. Tag each scheduled reattempt with a generation number. A superseded block does nothing apart from releasing the subscription pool slot it holds. It checks before handing off to the Matter queue, so it never keeps the slot while the current reattempt's pool item is turned away. * [Darwin] Wait for the reattempt dispatch in the superseded-timer tests The after-dispatch superseded-timer tests blocked the Matter queue for a fixed three seconds and then superseded the reattempt, assuming the earlier timer had queued its Matter-queue block by then. If the timer ran late, the reset happened first and the before-dispatch check rejected the timer instead, so the tests could pass without reaching the on-queue generation check they are meant to cover. Add a debug-only delegate callback that fires after the reattempt block has handed its work to the Matter queue, and have the tests wait for it while the Matter queue is blocked before superseding the reattempt. * [Darwin] Start the after-dispatch timer inside the blocked Matter-queue turn The after-dispatch superseded-timer tests issued their first reset in one Matter-queue block and only then blocked the queue in a second block. If the test thread was delayed by more than the reattempt delay between the two, the first timer could run its Matter-queue block before the queue was blocked, and the test no longer exercised the interleaving it is for. Issue the first reset inside the block that blocks the queue and waits for the dispatch. The tests also stamped the reattempt's start time from the internal state change, which reaches the test on its delegate queue and can be late. Stamp it from the subscription-setup-started hook, which the device calls synchronously after entering the subscribing state. * [Darwin] Test that superseded reattempt timers leave only the survivor's pool slot With a one-slot subscription pool, a Thread device that resets three times in a row has two superseded reattempt timers and one survivor. Each superseded timer takes the pool slot when it runs and must give it back. Check that once the surviving reattempt is subscribing and holding the slot, the pool holds exactly that one item: a superseded timer that kept its slot would leave more, and one that released the survivor's would leave none. * [Darwin] Explain why a superseded reattempt on the Matter queue leaves the pool slot alone The generation was already checked when the pool ran resubscriptionBlock, so a change seen on the Matter queue means whatever changed it also cleared the subscription pool work.
diff --git a/src/darwin/Framework/CHIP/MTRDevice_Concrete.mm b/src/darwin/Framework/CHIP/MTRDevice_Concrete.mm index f859d2d..ab50634 100644 --- a/src/darwin/Framework/CHIP/MTRDevice_Concrete.mm +++ b/src/darwin/Framework/CHIP/MTRDevice_Concrete.mm
@@ -455,6 +455,7 @@ - (BOOL)unitTestTimeUpdateShortDelayIsZero:(MTRDevice *)device; - (NSNumber *)unitTestTimeSynchronizationLossDetectionCadenceOverride:(MTRDevice *)device; - (void)unitTestTimeSynchronizationLossDetectedForDevice:(MTRDevice *)device; +- (void)unitTestSubscriptionReattemptDispatchedForDevice:(MTRDevice *)device; @end #endif @@ -485,6 +486,8 @@ // _setupSubscriptionWithReason or via the auto-resubscribe behavior // of the ReadClient). Nil if we have had no such failures. NSDate * _Nullable _lastSubscriptionFailureTime; + // Bumped each time a reattempt is scheduled; a timer whose captured value no longer matches was superseded. + NSUInteger _subscriptionReattemptGeneration; MTRDeviceConnectivityMonitor * _connectivityMonitor; // This boolean keeps track of any device configuration changes received in an attribute report. @@ -1890,6 +1893,7 @@ } self.reattemptingSubscription = YES; + NSUInteger reattemptGeneration = ++_subscriptionReattemptGeneration; NSTimeInterval secondsToWait; if (_lastSubscriptionAttemptWait < MTRDEVICE_SUBSCRIPTION_ATTEMPT_MIN_WAIT_SECONDS) { @@ -1920,16 +1924,38 @@ // Call _reattemptSubscriptionNowIfNeededWithReason when timer fires - if subscription is // in a better state at that time this will be a no-op. + BOOL deviceUsesThread = [self _deviceUsesThread]; mtr_weakify(self); auto resubscriptionBlock = ^(MTRAsyncWorkCompletionBlock _Nullable poolWorkCompletion) { mtr_strongify(self); VerifyOrReturn(self, MTR_LOG_DEBUG("_doHandleSubscriptionReset resubscriptionBlock called with nil MTRDevice")); + { + std::lock_guard lock(self->_lock); + if (self->_subscriptionReattemptGeneration != reattemptGeneration) { + MTR_LOG("%@ ignoring superseded subscription reattempt timer before dispatch", self); + if (deviceUsesThread) { + // The pool ready handler calls this block right after taking the slot on the device + // queue, so the slot is ours or already cleared. + [self _clearSubscriptionPoolWorkIfOwnedBy:poolWorkCompletion]; + } + return; + } + } + [self->_deviceController asyncDispatchToMatterQueue:^{ mtr_strongify(self); VerifyOrReturn(self, MTR_LOG_DEBUG("_doHandleSubscriptionReset resubscriptionBlock asyncDispatchToMatterQueue called back with nil MTRDevice")); std::lock_guard lock(self->_lock); + if (self->_subscriptionReattemptGeneration != reattemptGeneration) { + MTR_LOG("%@ ignoring superseded subscription reattempt timer on the Matter queue", self); + // Note: we claim the subscription pool work slot right before resubscriptionBlock, is called. + // We already checked the generation during the initial call to resubscriptionBlock, so if it's + // changed since then, whatever changed the generation also cleared our subscription pool + // work and we don't need to do that here. + return; + } [self _reattemptSubscriptionNowIfNeededWithReason:@"got subscription reset"]; } errorHandler:^(NSError * _Nonnull error) { @@ -1941,10 +1967,18 @@ std::lock_guard lock(self->_lock); [self _clearSubscriptionPoolWorkIfOwnedBy:poolWorkCompletion]; }]; + +#ifdef DEBUG + [self _lockAndCallDelegatesWithBlock:^(id testDelegate) { + if ([testDelegate respondsToSelector:@selector(unitTestSubscriptionReattemptDispatchedForDevice:)]) { + [testDelegate unitTestSubscriptionReattemptDispatchedForDevice:self]; + } + }]; +#endif }; int64_t resubscriptionDelayNs = static_cast<int64_t>(secondsToWait * NSEC_PER_SEC); - if ([self _deviceUsesThread]) { + if (deviceUsesThread) { // For Thread-enabled devices, schedule the _reattemptSubscriptionNowIfNeededWithReason call to run in the subscription pool NSString * description = [NSString stringWithFormat:@"MTRDevice resubscription (%p)", self]; [self _scheduleSubscriptionPoolWork:resubscriptionBlock skipIfResetSince:nil inNanoseconds:resubscriptionDelayNs description:description];
diff --git a/src/darwin/Framework/CHIPTests/MTRDeviceTests.m b/src/darwin/Framework/CHIPTests/MTRDeviceTests.m index 6adca6e..ecd75b1 100644 --- a/src/darwin/Framework/CHIPTests/MTRDeviceTests.m +++ b/src/darwin/Framework/CHIPTests/MTRDeviceTests.m
@@ -8550,6 +8550,157 @@ @end +@interface MTRDeviceResubscriptionTimerTests : MTRTestCase +@end + +@implementation MTRDeviceResubscriptionTimerTests + +- (void)_checkSupersededResubscriptionTimersWithThread:(BOOL)thread + subscriptionPoolWidth:(NSInteger)poolWidth + blockingMatterQueueFor:(NSTimeInterval)blockSeconds + supersedingWhileBlocked:(BOOL)supersedeWhileBlocked +{ + [[NSUserDefaults standardUserDefaults] setInteger:poolWidth forKey:kDefaultSubscriptionPoolSizeOverrideKey]; + MTRDeviceController * controller = [self createControllerOnTestFabric]; + [[NSUserDefaults standardUserDefaults] removeObjectForKey:kDefaultSubscriptionPoolSizeOverrideKey]; + XCTAssertNotNil(controller); + __auto_type * device = [MTRDevice deviceWithNodeID:@(0x12344399) controller:controller]; + dispatch_queue_t queue = dispatch_queue_create("superseded-resubscription-timer", DISPATCH_QUEUE_SERIAL); + + __auto_type * delegate = [[MTRDeviceTestDelegateWithSubscriptionSetupOverride alloc] init]; + delegate.skipSetupSubscription = YES; + delegate.pretendThreadEnabled = thread; + + XCTestExpectation * subscribingExpectation = [self expectationWithDescription:@"Reattempt started a subscription"]; + // Called synchronously right after the device enters the subscribing state, so the time isn't delayed by delegate delivery. + __block NSDate * subscribingTime = nil; + delegate.onSubscriptionSetupStarted = ^{ + if (subscribingTime == nil) { + subscribingTime = [NSDate now]; + [subscribingExpectation fulfill]; + } + }; + + dispatch_semaphore_t reattemptDispatched = dispatch_semaphore_create(0); + delegate.onSubscriptionReattemptDispatched = ^{ + dispatch_semaphore_signal(reattemptDispatched); + }; + + [device setDelegate:delegate queue:queue]; + + __block NSDate * finalResetTime = nil; + // When superseding while the Matter queue is blocked, the first reset happens inside the blocking block below, so its + // timer can't run its Matter-queue block before the queue is blocked. + for (int i = 0; i < (supersedeWhileBlocked ? 0 : 3); i++) { + [controller syncRunOnWorkQueue:^{ + device.reattemptingSubscription = NO; + finalResetTime = [NSDate now]; + [device _handleSubscriptionReset:nil]; + } error:nil]; + } + if (blockSeconds > 0 || supersedeWhileBlocked) { + [controller syncRunOnWorkQueue:^{ + if (supersedeWhileBlocked) { + device.reattemptingSubscription = NO; + [device _handleSubscriptionReset:nil]; + } + [NSThread sleepForTimeInterval:blockSeconds]; + if (supersedeWhileBlocked) { + // Supersede only once the timer has queued its Matter-queue block, so the on-queue check is what rejects it. + XCTAssertEqual(dispatch_semaphore_wait(reattemptDispatched, dispatch_time(DISPATCH_TIME_NOW, 10 * NSEC_PER_SEC)), 0); + device.reattemptingSubscription = NO; + finalResetTime = [NSDate now]; + [device _handleSubscriptionReset:nil]; + } + } error:nil]; + } + + [self waitForExpectations:@[ subscribingExpectation ] timeout:15]; + NSTimeInterval expectedReattemptSeconds = supersedeWhileBlocked ? 2 : 4; + XCTAssertGreaterThanOrEqual([subscribingTime timeIntervalSinceDate:finalResetTime], expectedReattemptSeconds - 0.5); + + [device removeDelegate:delegate]; + [controller syncRunOnWorkQueue:^{ + } error:nil]; + [controller removeDevice:device]; +} + +- (void)test001_SupersededResubscriptionTimerDoesNotFireEarly +{ + [self _checkSupersededResubscriptionTimersWithThread:NO subscriptionPoolWidth:1 blockingMatterQueueFor:0 supersedingWhileBlocked:NO]; +} + +- (void)test002_SupersededResubscriptionTimerDoesNotFireEarlyInSubscriptionPool +{ + [self _checkSupersededResubscriptionTimersWithThread:YES subscriptionPoolWidth:1 blockingMatterQueueFor:0 supersedingWhileBlocked:NO]; +} + +- (void)test003_SupersededResubscriptionTimerDoesNotStallSubscriptionPool +{ + [self _checkSupersededResubscriptionTimersWithThread:YES subscriptionPoolWidth:2 blockingMatterQueueFor:5.0 supersedingWhileBlocked:NO]; +} + +- (void)test004_SupersededResubscriptionTimerAfterDispatchDoesNotFireEarly +{ + [self _checkSupersededResubscriptionTimersWithThread:NO subscriptionPoolWidth:1 blockingMatterQueueFor:0 supersedingWhileBlocked:YES]; +} + +- (void)test005_SupersededResubscriptionTimerAfterDispatchDoesNotFireEarlyInSubscriptionPool +{ + [self _checkSupersededResubscriptionTimersWithThread:YES subscriptionPoolWidth:1 blockingMatterQueueFor:0 supersedingWhileBlocked:YES]; +} + +- (void)test006_SupersededResubscriptionTimersReleaseOnlyTheirOwnPoolSlot +{ + // Pins the owner-checked slot release in the superseded branch; no behaviour change. + // Once the surviving reattempt holds the pool slot, the superseded timers that ran + // must leave exactly that one item in the pool: none stranded, and the survivor's not released. + [[NSUserDefaults standardUserDefaults] setInteger:1 forKey:kDefaultSubscriptionPoolSizeOverrideKey]; + MTRDeviceController * controller = [self createControllerOnTestFabric]; + [[NSUserDefaults standardUserDefaults] removeObjectForKey:kDefaultSubscriptionPoolSizeOverrideKey]; + XCTAssertNotNil(controller); + __auto_type * device = [MTRDevice deviceWithNodeID:@(0x12344399) controller:controller]; + dispatch_queue_t queue = dispatch_queue_create("superseded-resubscription-pool-slot", DISPATCH_QUEUE_SERIAL); + + __auto_type * delegate = [[MTRDeviceTestDelegateWithSubscriptionSetupOverride alloc] init]; + delegate.skipSetupSubscription = YES; + delegate.pretendThreadEnabled = YES; + + XCTestExpectation * subscribingExpectation = [self expectationWithDescription:@"Surviving reattempt started a subscription"]; + delegate.onInternalStateChanged = ^{ + if ([device _getInternalState] == MTRInternalDeviceStateSubscribing) { + [subscribingExpectation fulfill]; + } + }; + subscribingExpectation.assertForOverFulfill = NO; + + [device setDelegate:delegate queue:queue]; + NSUInteger baselinePoolItemCount = controller.concurrentSubscriptionPool.itemCount; + + for (int i = 0; i < 3; i++) { + [controller syncRunOnWorkQueue:^{ + device.reattemptingSubscription = NO; + [device _handleSubscriptionReset:nil]; + } error:nil]; + } + [self waitForExpectations:@[ subscribingExpectation ] timeout:15]; + + [device unitTestSyncRunOnDeviceQueue:^{ + ; + }]; + [controller syncRunOnWorkQueue:^{ + } error:nil]; + // skipSetupSubscription leaves the survivor holding its slot. + XCTAssertEqual(controller.concurrentSubscriptionPool.itemCount, baselinePoolItemCount + 1); + + [device removeDelegate:delegate]; + [controller syncRunOnWorkQueue:^{ + } error:nil]; + [controller removeDevice:device]; +} + +@end + @interface MTRDeviceEncoderTests : XCTestCase @end
diff --git a/src/darwin/Framework/CHIPTests/TestHelpers/MTRDeviceTestDelegate.h b/src/darwin/Framework/CHIPTests/TestHelpers/MTRDeviceTestDelegate.h index 596b504..af12f42 100644 --- a/src/darwin/Framework/CHIPTests/TestHelpers/MTRDeviceTestDelegate.h +++ b/src/darwin/Framework/CHIPTests/TestHelpers/MTRDeviceTestDelegate.h
@@ -50,6 +50,8 @@ @property (atomic, copy, nullable) dispatch_block_t onTimeSynchronizationLossDetected; @property (atomic) BOOL forceTimeUpdateShortDelayToZero; @property (atomic, nullable) NSNumber * timeSynchronizationLossDetectionCadenceOverride; +// Called after a subscription reattempt timer has handed its work to the Matter queue. +@property (atomic, copy, nullable) dispatch_block_t onSubscriptionReattemptDispatched; @end @interface MTRDeviceTestDelegateWithSubscriptionSetupOverride : MTRDeviceTestDelegate
diff --git a/src/darwin/Framework/CHIPTests/TestHelpers/MTRDeviceTestDelegate.m b/src/darwin/Framework/CHIPTests/TestHelpers/MTRDeviceTestDelegate.m index c582b1e..f8e109e 100644 --- a/src/darwin/Framework/CHIPTests/TestHelpers/MTRDeviceTestDelegate.m +++ b/src/darwin/Framework/CHIPTests/TestHelpers/MTRDeviceTestDelegate.m
@@ -165,6 +165,13 @@ } } +- (void)unitTestSubscriptionReattemptDispatchedForDevice:(MTRDevice *)device +{ + if (self.onSubscriptionReattemptDispatched != nil) { + self.onSubscriptionReattemptDispatched(); + } +} + - (void)unitTestSetUTCTimeInvokedForDevice:(MTRDevice *)device error:(NSError * _Nullable)error { if (self.onUTCTimeSet != nil) {
diff --git a/src/darwin/Framework/CHIPTests/TestHelpers/MTRTestDeclarations.h b/src/darwin/Framework/CHIPTests/TestHelpers/MTRTestDeclarations.h index 9340864..e35fa0f 100644 --- a/src/darwin/Framework/CHIPTests/TestHelpers/MTRTestDeclarations.h +++ b/src/darwin/Framework/CHIPTests/TestHelpers/MTRTestDeclarations.h
@@ -83,6 +83,9 @@ expectedValueInterval:(NSNumber *)expectedValueInterval expectedValueID:(uint64_t *)expectedValueID; - (void)removeExpectedValuesForAttributePaths:(NSArray<MTRAttributePath *> *)attributePaths expectedValueID:(uint64_t)expectedValueID; +- (void)_handleSubscriptionReset:(NSNumber * _Nullable)retryDelay; + +@property (nonatomic) BOOL reattemptingSubscription; @property (nonatomic, readonly, nullable) NSNumber * highestObservedEventNumber; @property (nonatomic, readonly) MTRAsyncWorkQueue<MTRDevice *> * asyncWorkQueue;