diff --git a/src/darwin/Framework/CHIP/MTRAsyncWorkQueue.h b/src/darwin/Framework/CHIP/MTRAsyncWorkQueue.h index 598bbf00f5e690..f147307fab7012 100644 --- a/src/darwin/Framework/CHIP/MTRAsyncWorkQueue.h +++ b/src/darwin/Framework/CHIP/MTRAsyncWorkQueue.h @@ -228,6 +228,9 @@ MTR_TESTABLE - (BOOL)hasDuplicateForTypeID:(NSUInteger)opaqueDuplicateTypeID workItemData:(id)opaqueWorkItemData; +// Returns current count of queued items. +- (NSUInteger)itemCount; + /// Cancels and removes all work items. - (void)invalidate; @end diff --git a/src/darwin/Framework/CHIP/MTRAsyncWorkQueue.mm b/src/darwin/Framework/CHIP/MTRAsyncWorkQueue.mm index 4d82fded930b87..de3faee18a3f5a 100644 --- a/src/darwin/Framework/CHIP/MTRAsyncWorkQueue.mm +++ b/src/darwin/Framework/CHIP/MTRAsyncWorkQueue.mm @@ -433,6 +433,12 @@ - (BOOL)hasDuplicateForTypeID:(NSUInteger)opaqueDuplicateTypeID workItemData:(id return NO; } +- (NSUInteger)itemCount +{ + std::lock_guard lock(_lock); + return _items.count; +} + @end NS_ASSUME_NONNULL_END diff --git a/src/darwin/Framework/CHIP/MTRDevice.mm b/src/darwin/Framework/CHIP/MTRDevice.mm index 9ce2e3d4026f68..d8fc52b1a2fc6e 100644 --- a/src/darwin/Framework/CHIP/MTRDevice.mm +++ b/src/darwin/Framework/CHIP/MTRDevice.mm @@ -209,6 +209,24 @@ bool HaveSubscriptionEstablishedRightNow(MTRInternalDeviceState state) { return state == MTRInternalDeviceStateInitialSubscriptionEstablished || state == MTRInternalDeviceStateLaterSubscriptionEstablished; } + +NSString * InternalDeviceStateString(MTRInternalDeviceState state) +{ + switch (state) { + case MTRInternalDeviceStateUnsubscribed: + return @"Unsubscribed"; + case MTRInternalDeviceStateSubscribing: + return @"Subscribing"; + case MTRInternalDeviceStateInitialSubscriptionEstablished: + return @"InitialSubscriptionEstablished"; + case MTRInternalDeviceStateResubscribing: + return @"Resubscribing"; + case MTRInternalDeviceStateLaterSubscriptionEstablished: + return @"LaterSubscriptionEstablished"; + default: + return @"Unknown"; + } +} } // anonymous namespace typedef NS_ENUM(NSUInteger, MTRDeviceExpectedValueFieldIndex) { @@ -355,8 +373,11 @@ - (BOOL)isEqual:(id)object @interface MTRDevice () @property (nonatomic, readonly) os_unfair_lock lock; // protects the caches and device state // protects against concurrent time updates by guarding timeUpdateScheduled flag which manages time updates scheduling, -// and protects device calls to setUTCTime and setDSTOffset +// and protects device calls to setUTCTime and setDSTOffset. This can't just be replaced with "lock", because the time +// update code calls public APIs like readAttributeWithEndpointID:.. (which attempt to take "lock") while holding +// whatever lock protects the time sync bits. @property (nonatomic, readonly) os_unfair_lock timeSyncLock; + @property (nonatomic) chip::FabricIndex fabricIndex; @property (nonatomic) NSMutableArray *> * unreportedEvents; @property (nonatomic) BOOL receivingReport; @@ -482,6 +503,27 @@ @implementation MTRDevice { id _systemTimeChangeObserverToken; NSMutableSet * _delegates; + + // Protects mutable state used by our description getter. This is a separate lock from "lock" + // so that we don't need to worry about getting our description while holding "lock" (e.g due to + // logging self). This lock _must_ be held narrowly, with no other lock acquisitions allowed + // while it's held, to avoid deadlock. + os_unfair_lock _descriptionLock; + + // State used by our description getter: access to these must be protected by descriptionLock. + NSNumber * _Nullable _vid; // nil if unknown + NSNumber * _Nullable _pid; // nil if unknown + // _allNetworkFeatures is a bitwise or of the feature maps of all network commissioning clusters + // present on the device, or nil if there aren't any. + NSNumber * _Nullable _allNetworkFeatures; + // Copy of _internalDeviceState that is safe to use in description. + MTRInternalDeviceState _internalDeviceStateForDescription; + // Copy of _lastSubscriptionAttemptWait that is safe to use in description. + uint32_t _lastSubscriptionAttemptWaitForDescription; + // Most recent entry in _mostRecentReportTimes, if any. + NSDate * _Nullable _mostRecentReportTimeForDescription; + // Copy of _lastSubscriptionFailureTime that is safe to use in description. + NSDate * _Nullable _lastSubscriptionFailureTimeForDescription; } - (instancetype)initForSubclasses @@ -498,6 +540,7 @@ - (instancetype)initWithNodeID:(NSNumber *)nodeID controller:(MTRDeviceControlle if (self = [super init]) { _lock = OS_UNFAIR_LOCK_INIT; _timeSyncLock = OS_UNFAIR_LOCK_INIT; + _descriptionLock = OS_UNFAIR_LOCK_INIT; _nodeID = [nodeID copy]; _fabricIndex = controller.fabricIndex; _deviceController = controller; @@ -507,6 +550,7 @@ - (instancetype)initWithNodeID:(NSNumber *)nodeID controller:(MTRDeviceControlle _asyncWorkQueue = [[MTRAsyncWorkQueue alloc] initWithContext:self]; _state = MTRDeviceStateUnknown; _internalDeviceState = MTRInternalDeviceStateUnsubscribed; + _internalDeviceStateForDescription = MTRInternalDeviceStateUnsubscribed; if (controller.controllerDataStore) { _persistedClusterData = [[NSCache alloc] init]; } else { @@ -543,8 +587,58 @@ - (void)dealloc - (NSString *)description { + id _Nullable vid; + id _Nullable pid; + NSNumber * _Nullable networkFeatures; + MTRInternalDeviceState internalDeviceState; + uint32_t lastSubscriptionAttemptWait; + NSDate * _Nullable mostRecentReportTime; + NSDate * _Nullable lastSubscriptionFailureTime; + { + std::lock_guard lock(_descriptionLock); + vid = _vid; + pid = _pid; + networkFeatures = _allNetworkFeatures; + internalDeviceState = _internalDeviceStateForDescription; + lastSubscriptionAttemptWait = _lastSubscriptionAttemptWaitForDescription; + mostRecentReportTime = _mostRecentReportTimeForDescription; + lastSubscriptionFailureTime = _lastSubscriptionFailureTimeForDescription; + } + + if (vid == nil) { + vid = @"Unknown"; + } + + if (pid == nil) { + pid = @"Unknown"; + } + + NSString * wifi; + NSString * thread; + if (networkFeatures == nil) { + wifi = @"NO"; + thread = @"NO"; + } else { + wifi = YES_NO(networkFeatures.unsignedLongLongValue & MTRNetworkCommissioningFeatureWiFiNetworkInterface); + thread = YES_NO(networkFeatures.unsignedLongLongValue & MTRNetworkCommissioningFeatureThreadNetworkInterface); + } + + NSString * reportAge; + if (mostRecentReportTime) { + reportAge = [NSString stringWithFormat:@" (%.0lfs ago)", -[mostRecentReportTime timeIntervalSinceNow]]; + } else { + reportAge = @""; + } + + NSString * subscriptionFailureAge; + if (lastSubscriptionFailureTime) { + subscriptionFailureAge = [NSString stringWithFormat:@" (%.0lfs ago)", -[lastSubscriptionFailureTime timeIntervalSinceNow]]; + } else { + subscriptionFailureAge = @""; + } + return [NSString - stringWithFormat:@"[fabric: %u, nodeID: 0x%016llX]", self, _fabricIndex, _nodeID.unsignedLongLongValue]; + stringWithFormat:@"", self, _deviceController.compressedFabricID.unsignedLongLongValue, _nodeID.unsignedLongLongValue, _nodeID.unsignedLongLongValue, vid, pid, wifi, thread, InternalDeviceStateString(internalDeviceState), static_cast(lastSubscriptionAttemptWait), static_cast(_asyncWorkQueue.itemCount), mostRecentReportTime, reportAge, lastSubscriptionFailureTime, subscriptionFailureAge, _deviceController.uniqueIdentifier]; } + (MTRDevice *)deviceWithNodeID:(NSNumber *)nodeID controller:(MTRDeviceController *)controller @@ -661,13 +755,11 @@ - (void)_performScheduledTimeUpdate - (NSArray *)_endpointsWithTimeSyncClusterServer { - auto partsList = [self readAttributeWithEndpointID:@(0) clusterID:@(MTRClusterIDTypeDescriptorID) attributeID:@(MTRAttributeIDTypeClusterDescriptorAttributePartsListID) params:nil]; - NSMutableArray * endpointsOnDevice = [self arrayOfNumbersFromAttributeValue:partsList]; - if (!endpointsOnDevice) { - endpointsOnDevice = [[NSMutableArray alloc] init]; + NSArray * endpointsOnDevice; + { + std::lock_guard lock(_lock); + endpointsOnDevice = [self _endpointList]; } - // Add Root node! - [endpointsOnDevice addObject:@(0)]; NSMutableArray * endpointsWithTimeSyncCluster = [[NSMutableArray alloc] init]; for (NSNumber * endpoint in endpointsOnDevice) { @@ -1160,6 +1252,10 @@ - (void)_changeInternalState:(MTRInternalDeviceState)state os_unfair_lock_assert_owner(&self->_lock); MTRInternalDeviceState lastState = _internalDeviceState; _internalDeviceState = state; + { + std::lock_guard lock(_descriptionLock); + _internalDeviceStateForDescription = _internalDeviceState; + } if (lastState != state) { MTR_LOG("%@ internal state change %lu => %lu", self, static_cast(lastState), static_cast(state)); @@ -1201,7 +1297,7 @@ - (void)_handleSubscriptionEstablished [self _stopConnectivityMonitoring]; // reset subscription attempt wait time when subscription succeeds - _lastSubscriptionAttemptWait = 0; + [self _setLastSubscriptionAttemptWait:0]; auto initialSubscribeStart = _initialSubscribeStart; // We no longer need to track subscribe latency for this device. @@ -1367,6 +1463,10 @@ - (void)_handleResubscriptionNeededWithDelay:(NSNumber *)resubscriptionDelayMs // former case we recently had a subscription and do not want to be forcing // retries immediately. _lastSubscriptionFailureTime = [NSDate now]; + { + std::lock_guard lock(_descriptionLock); + _lastSubscriptionFailureTimeForDescription = _lastSubscriptionFailureTime; + } deviceUsesThread = [self _deviceUsesThread]; @@ -1408,6 +1508,15 @@ - (void)_handleSubscriptionReset:(NSNumber * _Nullable)retryDelay [self _doHandleSubscriptionReset:retryDelay]; } +- (void)_setLastSubscriptionAttemptWait:(uint32_t)lastSubscriptionAttemptWait +{ + os_unfair_lock_assert_owner(&_lock); + _lastSubscriptionAttemptWait = lastSubscriptionAttemptWait; + + std::lock_guard lock(_descriptionLock); + _lastSubscriptionAttemptWaitForDescription = lastSubscriptionAttemptWait; +} + - (void)_doHandleSubscriptionReset:(NSNumber * _Nullable)retryDelay { os_unfair_lock_assert_owner(&_lock); @@ -1417,6 +1526,10 @@ - (void)_doHandleSubscriptionReset:(NSNumber * _Nullable)retryDelay // has given up completely. Those all count as "we have tried and failed to // subscribe". _lastSubscriptionFailureTime = [NSDate now]; + { + std::lock_guard lock(_descriptionLock); + _lastSubscriptionFailureTimeForDescription = _lastSubscriptionFailureTime; + } // if there is no delegate then also do not retry if (![self _delegateExists]) { @@ -1441,16 +1554,17 @@ - (void)_doHandleSubscriptionReset:(NSNumber * _Nullable)retryDelay // counter, so that we don't end up waiting for a long time if the next // attempt fails for some reason, and retry after whatever time period // the device told us to use. - _lastSubscriptionAttemptWait = 0; + [self _setLastSubscriptionAttemptWait:0]; secondsToWait = retryDelay.doubleValue; MTR_LOG("%@ resetting resubscribe attempt counter, and delaying by the server-provided delay: %f", self, secondsToWait); } else { - _lastSubscriptionAttemptWait *= 2; - if (_lastSubscriptionAttemptWait > MTRDEVICE_SUBSCRIPTION_ATTEMPT_MAX_WAIT_SECONDS) { - _lastSubscriptionAttemptWait = MTRDEVICE_SUBSCRIPTION_ATTEMPT_MAX_WAIT_SECONDS; + auto lastSubscriptionAttemptWait = _lastSubscriptionAttemptWait * 2; + if (lastSubscriptionAttemptWait > MTRDEVICE_SUBSCRIPTION_ATTEMPT_MAX_WAIT_SECONDS) { + lastSubscriptionAttemptWait = MTRDEVICE_SUBSCRIPTION_ATTEMPT_MAX_WAIT_SECONDS; } - secondsToWait = _lastSubscriptionAttemptWait; + [self _setLastSubscriptionAttemptWait:lastSubscriptionAttemptWait]; + secondsToWait = lastSubscriptionAttemptWait; } MTR_LOG("%@ scheduling to reattempt subscription in %f seconds", self, secondsToWait); @@ -1665,6 +1779,9 @@ - (void)_persistClusterDataAsNeeded - (void)unitTestSetMostRecentReportTimes:(NSMutableArray *)mostRecentReportTimes { _mostRecentReportTimes = mostRecentReportTimes; + + std::lock_guard lock(_descriptionLock); + _mostRecentReportTimeForDescription = [mostRecentReportTimes lastObject]; } #endif @@ -1719,6 +1836,11 @@ - (void)_scheduleClusterDataPersistence } [_mostRecentReportTimes addObject:[NSDate now]]; + { + std::lock_guard lock(_descriptionLock); + _mostRecentReportTimeForDescription = [_mostRecentReportTimes lastObject]; + } + // Calculate running average and update multiplier - need at least 2 items to calculate intervals if (_mostRecentReportTimes.count > 2) { NSTimeInterval cumulativeIntervals = 0; @@ -1784,6 +1906,10 @@ - (void)_resetStorageBehaviorState _clusterDataPersistenceFirstScheduledTime = nil; _mostRecentReportTimes = nil; + { + std::lock_guard lock(_descriptionLock); + _mostRecentReportTimeForDescription = nil; + } _deviceReportingExcessivelyStartTime = nil; _reportToPersistenceDelayCurrentMultiplier = 1; @@ -2236,6 +2362,10 @@ - (void)_setCachedAttributeValue:(MTRDeviceDataValueDictionary _Nullable)value f [clusterData storeValue:value forAttribute:path.attribute]; + if ([self _attributePathAffectsDescriptionData:path]) { + [self _updateAttributeDependentDescriptionData]; + } + if (value != nil && isFromSubscription && !_receivingPrimingReport @@ -2295,10 +2425,11 @@ - (void)_createDataVersionFilterListFromDictionary:(NSDictionary_deviceController syncGetCompressedFabricID]; + NSNumber * compressedFabricID = [self->_deviceController compressedFabricID]; if (!compressedFabricID) { MTR_LOG_ERROR("%@ could not get compressed fabricID", self); return; @@ -3652,7 +3783,7 @@ - (NSArray *)_getAttributesToReportWithReportedValues:(NSArray_lock); + using namespace chip::Tracing::DarwinFramework; MATTER_LOG_METRIC(kMetricDeviceVendorID, [self _informationalVendorID].unsignedShortValue); MATTER_LOG_METRIC(kMetricDeviceProductID, [self _informationalProductID].unsignedShortValue); @@ -4140,6 +4279,89 @@ - (void)_addInformationalAttributesToCurrentMetricScope MATTER_LOG_METRIC(kMetricDeviceUsesThread, usesThread); } +#pragma mark - Description handling + +- (BOOL)_attributePathAffectsDescriptionData:(MTRAttributePath *)path +{ + // Technically this does not need to be called while locked, but in + // practice it is, and we want to make sure it's clear that this function + // should never start taking our data lock. + os_unfair_lock_assert_owner(&_lock); + + switch (path.cluster.unsignedLongLongValue) { + case MTRClusterIDTypeBasicInformationID: { + switch (path.attribute.unsignedLongLongValue) { + case MTRAttributeIDTypeClusterBasicInformationAttributeVendorIDID: + case MTRAttributeIDTypeClusterBasicInformationAttributeProductIDID: + return YES; + default: + return NO; + } + } + case MTRClusterIDTypeNetworkCommissioningID: { + return path.attribute.unsignedLongLongValue == MTRAttributeIDTypeGlobalAttributeFeatureMapID; + } + default: + return NO; + } +} + +- (void)_updateAttributeDependentDescriptionData +{ + os_unfair_lock_assert_owner(&_lock); + + NSNumber * _Nullable vid = [self _informationalVendorID]; + NSNumber * _Nullable pid = [self _informationalProductID]; + NSNumber * _Nullable networkFeatures = [self _networkFeatures]; + + std::lock_guard lock(_descriptionLock); + _vid = vid; + _pid = pid; + _allNetworkFeatures = networkFeatures; +} + +- (NSArray *)_endpointList +{ + os_unfair_lock_assert_owner(&_lock); + + auto * partsListPath = [MTRAttributePath attributePathWithEndpointID:@(kRootEndpointId) + clusterID:@(MTRClusterIDTypeDescriptorID) + attributeID:@(MTRAttributeIDTypeClusterDescriptorAttributePartsListID)]; + auto * partsList = [self _cachedAttributeValueForPath:partsListPath]; + NSMutableArray * endpointsOnDevice = [self arrayOfNumbersFromAttributeValue:partsList]; + if (!endpointsOnDevice) { + endpointsOnDevice = [[NSMutableArray alloc] init]; + } + // Add Root node! + [endpointsOnDevice addObject:@(0)]; + return endpointsOnDevice; +} + +- (NSNumber * _Nullable)_networkFeatures +{ + NSNumber * _Nullable result = nil; + auto * endpoints = [self _endpointList]; + for (NSNumber * endpoint in endpoints) { + auto * featureMapPath = [MTRAttributePath attributePathWithEndpointID:endpoint + clusterID:@(MTRClusterIDTypeNetworkCommissioningID) + attributeID:@(MTRAttributeIDTypeGlobalAttributeFeatureMapID)]; + auto * featureMap = [self _informationalNumberAtAttributePath:featureMapPath]; + if (featureMap == nil) { + // No network commissioning cluster on this endpoint, or no known + // FeatureMap attribute value for it yet. + continue; + } + + if (result == nil) { + result = featureMap; + } else { + result = @(featureMap.unsignedLongLongValue | result.unsignedLongLongValue); + } + } + + return result; +} + @end /* BEGIN DRAGONS: Note methods here cannot be renamed, and are used by private callers, do not rename, remove or modify behavior here */ diff --git a/src/darwin/Framework/CHIP/MTRDeviceController.mm b/src/darwin/Framework/CHIP/MTRDeviceController.mm index 6c312d510a93a7..25a0e7d4dcd4c1 100644 --- a/src/darwin/Framework/CHIP/MTRDeviceController.mm +++ b/src/darwin/Framework/CHIP/MTRDeviceController.mm @@ -75,6 +75,7 @@ #include #include +#include #include #import @@ -107,8 +108,9 @@ using namespace chip::Tracing::DarwinFramework; @implementation MTRDeviceController { - // Atomic because it can be touched from multiple threads. + // Atomic because they can be touched from multiple threads. std::atomic _storedFabricIndex; + std::atomic> _storedCompressedFabricID; // queue used to serialize all work performed by the MTRDeviceController dispatch_queue_t _chipWorkQueue; @@ -278,6 +280,7 @@ - (instancetype)initWithFactory:(MTRDeviceControllerFactory *)factory _concurrentSubscriptionPool = [[MTRAsyncWorkQueue alloc] initWithContext:self width:concurrentSubscriptionPoolSize]; _storedFabricIndex = chip::kUndefinedFabricIndex; + _storedCompressedFabricID = std::nullopt; _storageBehaviorConfiguration = storageBehaviorConfiguration; } @@ -351,6 +354,7 @@ - (void)shutDownCppController // shutdown completes, in case it wants to write to storage as it // shuts down. _storedFabricIndex = chip::kUndefinedFabricIndex; + _storedCompressedFabricID = std::nullopt; delete commissionerToShutDown; if (_operationalCredentialsDelegate != nil) { _operationalCredentialsDelegate->SetDeviceCommissioner(nullptr); @@ -590,6 +594,7 @@ - (BOOL)startup:(MTRDeviceControllerStartupParamsInternal *)startupParams } self->_storedFabricIndex = fabricIdx; + self->_storedCompressedFabricID = _cppCommissioner->GetCompressedFabricId(); commissionerInitialized = YES; MTR_LOG("%@ startup succeeded for nodeID 0x%016llX", self, self->_cppCommissioner->GetNodeId()); @@ -1440,20 +1445,8 @@ - (BOOL)syncRunOnWorkQueueWithBoolReturnValue:(SyncWorkQueueBlockWithBoolReturnV - (nullable NSNumber *)compressedFabricID { - assertChipStackLockedByCurrentThread(); - - if (!_cppCommissioner) { - return nil; - } - - return @(_cppCommissioner->GetCompressedFabricId()); -} - -- (NSNumber * _Nullable)syncGetCompressedFabricID -{ - return [self syncRunOnWorkQueueWithReturnValue:^NSNumber * { - return [self compressedFabricID]; - } error:nil]; + auto storedValue = _storedCompressedFabricID.load(); + return storedValue.has_value() ? @(storedValue.value()) : nil; } - (CHIP_ERROR)isRunningOnFabric:(chip::FabricTable *)fabricTable diff --git a/src/darwin/Framework/CHIP/MTRDeviceController_Internal.h b/src/darwin/Framework/CHIP/MTRDeviceController_Internal.h index 925bbb284f3ab4..479dd8518d069f 100644 --- a/src/darwin/Framework/CHIP/MTRDeviceController_Internal.h +++ b/src/darwin/Framework/CHIP/MTRDeviceController_Internal.h @@ -79,8 +79,6 @@ NS_ASSUME_NONNULL_BEGIN /** * Will return the compressed fabric id of the fabric if the controller is * running, else nil. - * - * This property MUST be gotten from the Matter work queue. */ @property (nonatomic, readonly, nullable) NSNumber * compressedFabricID; @@ -266,8 +264,6 @@ NS_ASSUME_NONNULL_BEGIN - (MTRDevice *)deviceForNodeID:(NSNumber *)nodeID; - (void)removeDevice:(MTRDevice *)device; -- (NSNumber * _Nullable)syncGetCompressedFabricID; - /** * Since getSessionForNode now enqueues by the subscription pool for Thread * devices, MTRDevice needs a direct non-queued access because it already diff --git a/src/darwin/Framework/CHIP/MTRDevice_Concrete.mm b/src/darwin/Framework/CHIP/MTRDevice_Concrete.mm index a90b49d52b3139..e22b0b8edff243 100644 --- a/src/darwin/Framework/CHIP/MTRDevice_Concrete.mm +++ b/src/darwin/Framework/CHIP/MTRDevice_Concrete.mm @@ -219,6 +219,24 @@ bool HaveSubscriptionEstablishedRightNow(MTRInternalDeviceState state) { return state == MTRInternalDeviceStateInitialSubscriptionEstablished || state == MTRInternalDeviceStateLaterSubscriptionEstablished; } + +NSString * InternalDeviceStateString(MTRInternalDeviceState state) +{ + switch (state) { + case MTRInternalDeviceStateUnsubscribed: + return @"Unsubscribed"; + case MTRInternalDeviceStateSubscribing: + return @"Subscribing"; + case MTRInternalDeviceStateInitialSubscriptionEstablished: + return @"InitialSubscriptionEstablished"; + case MTRInternalDeviceStateResubscribing: + return @"Resubscribing"; + case MTRInternalDeviceStateLaterSubscriptionEstablished: + return @"LaterSubscriptionEstablished"; + default: + return @"Unknown"; + } +} } // anonymous namespace typedef NS_ENUM(NSUInteger, MTRDeviceExpectedValueFieldIndex) { @@ -265,8 +283,11 @@ typedef NS_ENUM(NSUInteger, MTRDeviceWorkItemDuplicateTypeID) { @interface MTRDevice_Concrete () @property (nonatomic, readonly) os_unfair_lock lock; // protects the caches and device state // protects against concurrent time updates by guarding timeUpdateScheduled flag which manages time updates scheduling, -// and protects device calls to setUTCTime and setDSTOffset +// and protects device calls to setUTCTime and setDSTOffset. This can't just be replaced with "lock", because the time +// update code calls public APIs like readAttributeWithEndpointID:.. (which attempt to take "lock") while holding +// whatever lock protects the time sync bits. @property (nonatomic, readonly) os_unfair_lock timeSyncLock; + @property (nonatomic) chip::FabricIndex fabricIndex; @property (nonatomic) NSMutableArray *> * unreportedEvents; @property (nonatomic) BOOL receivingReport; @@ -392,6 +413,27 @@ @implementation MTRDevice_Concrete { id _systemTimeChangeObserverToken; NSMutableSet * _delegates; + + // Protects mutable state used by our description getter. This is a separate lock from "lock" + // so that we don't need to worry about getting our description while holding "lock" (e.g due to + // logging self). This lock _must_ be held narrowly, with no other lock acquisitions allowed + // while it's held, to avoid deadlock. + os_unfair_lock _descriptionLock; + + // State used by our description getter: access to these must be protected by descriptionLock. + NSNumber * _Nullable _vid; // nil if unknown + NSNumber * _Nullable _pid; // nil if unknown + // _allNetworkFeatures is a bitwise or of the feature maps of all network commissioning clusters + // present on the device, or nil if there aren't any. + NSNumber * _Nullable _allNetworkFeatures; + // Copy of _internalDeviceState that is safe to use in description. + MTRInternalDeviceState _internalDeviceStateForDescription; + // Copy of _lastSubscriptionAttemptWait that is safe to use in description. + uint32_t _lastSubscriptionAttemptWaitForDescription; + // Most recent entry in _mostRecentReportTimes, if any. + NSDate * _Nullable _mostRecentReportTimeForDescription; + // Copy of _lastSubscriptionFailureTime that is safe to use in description. + NSDate * _Nullable _lastSubscriptionFailureTimeForDescription; } // synthesize superclass property readwrite accessors @@ -411,6 +453,7 @@ - (instancetype)initWithNodeID:(NSNumber *)nodeID controller:(MTRDeviceControlle if (self = [super initForSubclasses]) { _lock = OS_UNFAIR_LOCK_INIT; _timeSyncLock = OS_UNFAIR_LOCK_INIT; + _descriptionLock = OS_UNFAIR_LOCK_INIT; _nodeID = [nodeID copy]; _fabricIndex = controller.fabricIndex; _deviceController = controller; @@ -420,6 +463,7 @@ - (instancetype)initWithNodeID:(NSNumber *)nodeID controller:(MTRDeviceControlle _asyncWorkQueue = [[MTRAsyncWorkQueue alloc] initWithContext:self]; _state = MTRDeviceStateUnknown; _internalDeviceState = MTRInternalDeviceStateUnsubscribed; + _internalDeviceStateForDescription = MTRInternalDeviceStateUnsubscribed; if (controller.controllerDataStore) { _persistedClusterData = [[NSCache alloc] init]; } else { @@ -456,8 +500,58 @@ - (void)dealloc - (NSString *)description { + id _Nullable vid; + id _Nullable pid; + NSNumber * _Nullable networkFeatures; + MTRInternalDeviceState internalDeviceState; + uint32_t lastSubscriptionAttemptWait; + NSDate * _Nullable mostRecentReportTime; + NSDate * _Nullable lastSubscriptionFailureTime; + { + std::lock_guard lock(_descriptionLock); + vid = _vid; + pid = _pid; + networkFeatures = _allNetworkFeatures; + internalDeviceState = _internalDeviceStateForDescription; + lastSubscriptionAttemptWait = _lastSubscriptionAttemptWaitForDescription; + mostRecentReportTime = _mostRecentReportTimeForDescription; + lastSubscriptionFailureTime = _lastSubscriptionFailureTimeForDescription; + } + + if (vid == nil) { + vid = @"Unknown"; + } + + if (pid == nil) { + pid = @"Unknown"; + } + + NSString * wifi; + NSString * thread; + if (networkFeatures == nil) { + wifi = @"NO"; + thread = @"NO"; + } else { + wifi = YES_NO(networkFeatures.unsignedLongLongValue & MTRNetworkCommissioningFeatureWiFiNetworkInterface); + thread = YES_NO(networkFeatures.unsignedLongLongValue & MTRNetworkCommissioningFeatureThreadNetworkInterface); + } + + NSString * reportAge; + if (mostRecentReportTime) { + reportAge = [NSString stringWithFormat:@" (%.0lfs ago)", -[mostRecentReportTime timeIntervalSinceNow]]; + } else { + reportAge = @""; + } + + NSString * subscriptionFailureAge; + if (lastSubscriptionFailureTime) { + subscriptionFailureAge = [NSString stringWithFormat:@" (%.0lfs ago)", -[lastSubscriptionFailureTime timeIntervalSinceNow]]; + } else { + subscriptionFailureAge = @""; + } + return [NSString - stringWithFormat:@"[fabric: %u, nodeID: 0x%016llX]", self, _fabricIndex, _nodeID.unsignedLongLongValue]; + stringWithFormat:@"", self, _deviceController.compressedFabricID.unsignedLongLongValue, _nodeID.unsignedLongLongValue, _nodeID.unsignedLongLongValue, vid, pid, wifi, thread, InternalDeviceStateString(internalDeviceState), static_cast(lastSubscriptionAttemptWait), static_cast(_asyncWorkQueue.itemCount), mostRecentReportTime, reportAge, lastSubscriptionFailureTime, subscriptionFailureAge, _deviceController.uniqueIdentifier]; } + (MTRDevice *)deviceWithNodeID:(NSNumber *)nodeID controller:(MTRDeviceController *)controller @@ -574,13 +668,11 @@ - (void)_performScheduledTimeUpdate - (NSArray *)_endpointsWithTimeSyncClusterServer { - auto partsList = [self readAttributeWithEndpointID:@(0) clusterID:@(MTRClusterIDTypeDescriptorID) attributeID:@(MTRAttributeIDTypeClusterDescriptorAttributePartsListID) params:nil]; - NSMutableArray * endpointsOnDevice = [self arrayOfNumbersFromAttributeValue:partsList]; - if (!endpointsOnDevice) { - endpointsOnDevice = [[NSMutableArray alloc] init]; + NSArray * endpointsOnDevice; + { + std::lock_guard lock(_lock); + endpointsOnDevice = [self _endpointList]; } - // Add Root node! - [endpointsOnDevice addObject:@(0)]; NSMutableArray * endpointsWithTimeSyncCluster = [[NSMutableArray alloc] init]; for (NSNumber * endpoint in endpointsOnDevice) { @@ -1073,6 +1165,10 @@ - (void)_changeInternalState:(MTRInternalDeviceState)state os_unfair_lock_assert_owner(&self->_lock); MTRInternalDeviceState lastState = _internalDeviceState; _internalDeviceState = state; + { + std::lock_guard lock(_descriptionLock); + _internalDeviceStateForDescription = _internalDeviceState; + } if (lastState != state) { MTR_LOG("%@ internal state change %lu => %lu", self, static_cast(lastState), static_cast(state)); @@ -1114,7 +1210,7 @@ - (void)_handleSubscriptionEstablished [self _stopConnectivityMonitoring]; // reset subscription attempt wait time when subscription succeeds - _lastSubscriptionAttemptWait = 0; + [self _setLastSubscriptionAttemptWait:0]; auto initialSubscribeStart = _initialSubscribeStart; // We no longer need to track subscribe latency for this device. @@ -1280,6 +1376,10 @@ - (void)_handleResubscriptionNeededWithDelay:(NSNumber *)resubscriptionDelayMs // former case we recently had a subscription and do not want to be forcing // retries immediately. _lastSubscriptionFailureTime = [NSDate now]; + { + std::lock_guard lock(_descriptionLock); + _lastSubscriptionFailureTimeForDescription = _lastSubscriptionFailureTime; + } deviceUsesThread = [self _deviceUsesThread]; @@ -1321,6 +1421,15 @@ - (void)_handleSubscriptionReset:(NSNumber * _Nullable)retryDelay [self _doHandleSubscriptionReset:retryDelay]; } +- (void)_setLastSubscriptionAttemptWait:(uint32_t)lastSubscriptionAttemptWait +{ + os_unfair_lock_assert_owner(&_lock); + _lastSubscriptionAttemptWait = lastSubscriptionAttemptWait; + + std::lock_guard lock(_descriptionLock); + _lastSubscriptionAttemptWaitForDescription = lastSubscriptionAttemptWait; +} + - (void)_doHandleSubscriptionReset:(NSNumber * _Nullable)retryDelay { os_unfair_lock_assert_owner(&_lock); @@ -1330,6 +1439,10 @@ - (void)_doHandleSubscriptionReset:(NSNumber * _Nullable)retryDelay // has given up completely. Those all count as "we have tried and failed to // subscribe". _lastSubscriptionFailureTime = [NSDate now]; + { + std::lock_guard lock(_descriptionLock); + _lastSubscriptionFailureTimeForDescription = _lastSubscriptionFailureTime; + } // if there is no delegate then also do not retry if (![self _delegateExists]) { @@ -1354,16 +1467,17 @@ - (void)_doHandleSubscriptionReset:(NSNumber * _Nullable)retryDelay // counter, so that we don't end up waiting for a long time if the next // attempt fails for some reason, and retry after whatever time period // the device told us to use. - _lastSubscriptionAttemptWait = 0; + [self _setLastSubscriptionAttemptWait:0]; secondsToWait = retryDelay.doubleValue; MTR_LOG("%@ resetting resubscribe attempt counter, and delaying by the server-provided delay: %f", self, secondsToWait); } else { - _lastSubscriptionAttemptWait *= 2; - if (_lastSubscriptionAttemptWait > MTRDEVICE_SUBSCRIPTION_ATTEMPT_MAX_WAIT_SECONDS) { - _lastSubscriptionAttemptWait = MTRDEVICE_SUBSCRIPTION_ATTEMPT_MAX_WAIT_SECONDS; + auto lastSubscriptionAttemptWait = _lastSubscriptionAttemptWait * 2; + if (lastSubscriptionAttemptWait > MTRDEVICE_SUBSCRIPTION_ATTEMPT_MAX_WAIT_SECONDS) { + lastSubscriptionAttemptWait = MTRDEVICE_SUBSCRIPTION_ATTEMPT_MAX_WAIT_SECONDS; } - secondsToWait = _lastSubscriptionAttemptWait; + [self _setLastSubscriptionAttemptWait:lastSubscriptionAttemptWait]; + secondsToWait = lastSubscriptionAttemptWait; } MTR_LOG("%@ scheduling to reattempt subscription in %f seconds", self, secondsToWait); @@ -1578,6 +1692,9 @@ - (void)_persistClusterDataAsNeeded - (void)unitTestSetMostRecentReportTimes:(NSMutableArray *)mostRecentReportTimes { _mostRecentReportTimes = mostRecentReportTimes; + + std::lock_guard lock(_descriptionLock); + _mostRecentReportTimeForDescription = [mostRecentReportTimes lastObject]; } #endif @@ -1632,6 +1749,11 @@ - (void)_scheduleClusterDataPersistence } [_mostRecentReportTimes addObject:[NSDate now]]; + { + std::lock_guard lock(_descriptionLock); + _mostRecentReportTimeForDescription = [_mostRecentReportTimes lastObject]; + } + // Calculate running average and update multiplier - need at least 2 items to calculate intervals if (_mostRecentReportTimes.count > 2) { NSTimeInterval cumulativeIntervals = 0; @@ -1697,6 +1819,10 @@ - (void)_resetStorageBehaviorState _clusterDataPersistenceFirstScheduledTime = nil; _mostRecentReportTimes = nil; + { + std::lock_guard lock(_descriptionLock); + _mostRecentReportTimeForDescription = nil; + } _deviceReportingExcessivelyStartTime = nil; _reportToPersistenceDelayCurrentMultiplier = 1; @@ -2149,6 +2275,10 @@ - (void)_setCachedAttributeValue:(MTRDeviceDataValueDictionary _Nullable)value f [clusterData storeValue:value forAttribute:path.attribute]; + if ([self _attributePathAffectsDescriptionData:path]) { + [self _updateAttributeDependentDescriptionData]; + } + if (value != nil && isFromSubscription && !_receivingPrimingReport @@ -2208,10 +2338,11 @@ - (void)_createDataVersionFilterListFromDictionary:(NSDictionary_deviceController syncGetCompressedFabricID]; + NSNumber * compressedFabricID = [self->_deviceController compressedFabricID]; if (!compressedFabricID) { MTR_LOG_ERROR("%@ could not get compressed fabricID", self); return; @@ -3565,7 +3696,7 @@ - (NSArray *)_getAttributesToReportWithReportedValues:(NSArray_lock); + using namespace chip::Tracing::DarwinFramework; MATTER_LOG_METRIC(kMetricDeviceVendorID, [self _informationalVendorID].unsignedShortValue); MATTER_LOG_METRIC(kMetricDeviceProductID, [self _informationalProductID].unsignedShortValue); @@ -4053,6 +4192,89 @@ - (void)_addInformationalAttributesToCurrentMetricScope MATTER_LOG_METRIC(kMetricDeviceUsesThread, usesThread); } +#pragma mark - Description handling + +- (BOOL)_attributePathAffectsDescriptionData:(MTRAttributePath *)path +{ + // Technically this does not need to be called while locked, but in + // practice it is, and we want to make sure it's clear that this function + // should never start taking our data lock. + os_unfair_lock_assert_owner(&_lock); + + switch (path.cluster.unsignedLongLongValue) { + case MTRClusterIDTypeBasicInformationID: { + switch (path.attribute.unsignedLongLongValue) { + case MTRAttributeIDTypeClusterBasicInformationAttributeVendorIDID: + case MTRAttributeIDTypeClusterBasicInformationAttributeProductIDID: + return YES; + default: + return NO; + } + } + case MTRClusterIDTypeNetworkCommissioningID: { + return path.attribute.unsignedLongLongValue == MTRAttributeIDTypeGlobalAttributeFeatureMapID; + } + default: + return NO; + } +} + +- (void)_updateAttributeDependentDescriptionData +{ + os_unfair_lock_assert_owner(&_lock); + + NSNumber * _Nullable vid = [self _informationalVendorID]; + NSNumber * _Nullable pid = [self _informationalProductID]; + NSNumber * _Nullable networkFeatures = [self _networkFeatures]; + + std::lock_guard lock(_descriptionLock); + _vid = vid; + _pid = pid; + _allNetworkFeatures = networkFeatures; +} + +- (NSArray *)_endpointList +{ + os_unfair_lock_assert_owner(&_lock); + + auto * partsListPath = [MTRAttributePath attributePathWithEndpointID:@(kRootEndpointId) + clusterID:@(MTRClusterIDTypeDescriptorID) + attributeID:@(MTRAttributeIDTypeClusterDescriptorAttributePartsListID)]; + auto * partsList = [self _cachedAttributeValueForPath:partsListPath]; + NSMutableArray * endpointsOnDevice = [self arrayOfNumbersFromAttributeValue:partsList]; + if (!endpointsOnDevice) { + endpointsOnDevice = [[NSMutableArray alloc] init]; + } + // Add Root node! + [endpointsOnDevice addObject:@(0)]; + return endpointsOnDevice; +} + +- (NSNumber * _Nullable)_networkFeatures +{ + NSNumber * _Nullable result = nil; + auto * endpoints = [self _endpointList]; + for (NSNumber * endpoint in endpoints) { + auto * featureMapPath = [MTRAttributePath attributePathWithEndpointID:endpoint + clusterID:@(MTRClusterIDTypeNetworkCommissioningID) + attributeID:@(MTRAttributeIDTypeGlobalAttributeFeatureMapID)]; + auto * featureMap = [self _informationalNumberAtAttributePath:featureMapPath]; + if (featureMap == nil) { + // No network commissioning cluster on this endpoint, or no known + // FeatureMap attribute value for it yet. + continue; + } + + if (result == nil) { + result = featureMap; + } else { + result = @(featureMap.unsignedLongLongValue | result.unsignedLongLongValue); + } + } + + return result; +} + @end /* BEGIN DRAGONS: Note methods here cannot be renamed, and are used by private callers, do not rename, remove or modify behavior here */