Skip to content

Commit

Permalink
Include work item id in various log messages as per review
Browse files Browse the repository at this point in the history
  • Loading branch information
@ksperling-apple
ksperling-apple committed Oct 5, 2023
1 parent 5fed982 commit bd6d2c1
Show file tree
Hide file tree
Showing 3 changed files with 20 additions and 16 deletions.
4 changes: 4 additions & 0 deletions src/darwin/Framework/CHIP/MTRAsyncWorkQueue.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -107,6 +107,10 @@ MTR_TESTABLE
/// Creates a work item that will run on the specified dispatch queue.
- (instancetype)initWithQueue:(dispatch_queue_t)queue;

/// A unique (modulo overflow) ID automatically assigned to each work item for
/// the purpose of correlating log messages from the work queue.
@property (readonly, nonatomic) NSUInteger uniqueID;

/// Called by the work queue to start this work item.
///
/// Will be called on the dispatch queue associated with this item.
Expand Down
5 changes: 0 additions & 5 deletions src/darwin/Framework/CHIP/MTRAsyncWorkQueue.mm
View file
Original file line number Diff line number Diff line change
Expand Up @@ -44,11 +44,6 @@ typedef NS_ENUM(NSInteger, MTRAsyncWorkItemState) {
}
};

MTR_DIRECT_MEMBERS
@interface MTRAsyncWorkItem ()
@property (readonly, nonatomic) NSUInteger uniqueID;
@end

MTR_DIRECT_MEMBERS
@implementation MTRAsyncWorkItem {
dispatch_queue_t _queue;
Expand Down
27 changes: 16 additions & 11 deletions src/darwin/Framework/CHIP/MTRDevice.mm
View file
Original file line number Diff line number Diff line change
Expand Up @@ -893,6 +893,7 @@ static BOOL AttributeHasChangesOmittedQuality(MTRAttributePath * attributePath)

// Create work item, set ready handler to perform task, then enqueue the work
MTRAsyncWorkItem * workItem = [[MTRAsyncWorkItem alloc] initWithQueue:self.queue];
NSUInteger workItemID = workItem.uniqueID; // capture only the ID, not the work item
[workItem setBatchingID:MTRDeviceWorkItemBatchingReadID data:readRequests handler:^(id opaqueDataCurrent, id opaqueDataNext) {
mtr_hide(self); // don't capture self accidentally
NSMutableArray<NSArray *> * readRequestsCurrent = opaqueDataCurrent;
Expand All @@ -902,21 +903,23 @@ static BOOL AttributeHasChangesOmittedQuality(MTRAttributePath * attributePath)
while (readRequestsNext.count) {
// Can only read up to 9 paths at a time, per spec
if (readRequestsCurrent.count >= 9) {
MTR_LOG_INFO("Batching cannot add more work, current item is full");
MTR_LOG_INFO("Batching read attribute work %tu: cannot add more work, item is full", workItemID);
return outcome;
}

// if params don't match then they cannot be merged
if (![readRequestsNext[0][MTRDeviceReadRequestFieldParamsIndex]
isEqual:readRequestsCurrent[0][MTRDeviceReadRequestFieldParamsIndex]]) {
MTR_LOG_INFO("Batching cannot add more work, parameter mismatch");
MTR_LOG_INFO("Batching read attribute work %tu: cannot add more work, parameter mismatch", workItemID);
return outcome;
}

// merge the next item's first request into the current item's list
MTR_LOG_INFO("Batching %@ => %tu total", readRequestsNext[0], readRequestsCurrent.count);
[readRequestsCurrent addObject:readRequestsNext[0]];
auto readItem = readRequestsNext.firstObject;
[readRequestsNext removeObjectAtIndex:0];
[readRequestsCurrent addObject:readItem];
MTR_LOG_INFO("Batching read attribute work %tu: added %@ (now %tu requests total)",
workItemID, readItem, readRequestsCurrent.count);
outcome = MTRBatchedPartially;
}
NSCAssert(readRequestsNext.count == 0, @"should have batched everything or returned early");
Expand All @@ -926,7 +929,7 @@ static BOOL AttributeHasChangesOmittedQuality(MTRAttributePath * attributePath)
mtr_hide(self); // don't capture self accidentally
for (NSArray * readItem in readRequests) {
if ([readItem isEqual:opaqueItemData]) {
MTR_LOG_DEFAULT("Read attribute duplicate check found %@ - report duplicate", readItem);
MTR_LOG_DEFAULT("Read attribute work %tu report duplicate %@", workItemID, readItem);
*isDuplicate = YES;
*stop = YES;
return;
Expand All @@ -937,7 +940,7 @@ static BOOL AttributeHasChangesOmittedQuality(MTRAttributePath * attributePath)
[workItem setReadyHandler:^(MTRDevice * self, NSInteger retryCount, MTRAsyncWorkCompletionBlock completion) {
// Sanity check
if (readRequests.count == 0) {
MTR_LOG_ERROR("Read attribute work contained no read requests");
MTR_LOG_ERROR("Read attribute work %tu contained no read requests", workItemID);
completion(MTRAsyncWorkComplete);
return;
}
Expand All @@ -962,16 +965,16 @@ static BOOL AttributeHasChangesOmittedQuality(MTRAttributePath * attributePath)
if (values) {
// Since the format is the same data-value dictionary, this looks like an
// attribute report
MTR_LOG_INFO("Read attribute result: %@", values);
MTR_LOG_INFO("Read attribute work %tu result: %@", workItemID, values);
[self _handleAttributeReport:values];
}

// TODO: better retry logic
if (error && (retryCount < 2)) {
MTR_LOG_ERROR("Read attribute failed (will retry): %@", error);
MTR_LOG_ERROR("Read attribute work %tu failed (will retry): %@", workItemID, error);
completion(MTRAsyncWorkNeedsRetry);
} else {
MTR_LOG_DEFAULT("Read attribute failed (giving up): %@", error);
MTR_LOG_DEFAULT("Read attribute work %tu failed (giving up): %@", workItemID, error);
completion(MTRAsyncWorkComplete);
}
}];
Expand Down Expand Up @@ -1004,6 +1007,7 @@ - (void)writeAttributeWithEndpointID:(NSNumber *)endpointID
expectedValueID:&expectedValueID];

MTRAsyncWorkItem * workItem = [[MTRAsyncWorkItem alloc] initWithQueue:self.queue];
NSUInteger workItemID = workItem.uniqueID; // capture only the ID, not the work item
// The write operation will install a duplicate check handler, to return NO for "isDuplicate". Since a write operation may
// change values, only read requests after this should be considered for duplicate requests.
[workItem setDuplicateTypeID:MTRDeviceWorkItemDuplicateReadTypeID handler:^(id opaqueItemData, BOOL * isDuplicate, BOOL * stop) {
Expand All @@ -1021,7 +1025,7 @@ - (void)writeAttributeWithEndpointID:(NSNumber *)endpointID
queue:self.queue
completion:^(NSArray<NSDictionary<NSString *, id> *> * _Nullable values, NSError * _Nullable error) {
if (error) {
MTR_LOG_ERROR("Write attribute failed: %@", error);
MTR_LOG_ERROR("Write attribute work %tu failed: %@", workItemID, error);
[self removeExpectedValueForAttributePath:attributePath expectedValueID:expectedValueID];
}
completion(MTRAsyncWorkComplete);
Expand Down Expand Up @@ -1086,6 +1090,7 @@ - (void)_invokeCommandWithEndpointID:(NSNumber *)endpointID
}
}
MTRAsyncWorkItem * workItem = [[MTRAsyncWorkItem alloc] initWithQueue:self.queue];
NSUInteger workItemID = workItem.uniqueID; // capture only the ID, not the work item
// The command operation will install a duplicate check handler, to return NO for "isDuplicate". Since a command operation may
// change values, only read requests after this should be considered for duplicate requests.
[workItem setDuplicateTypeID:MTRDeviceWorkItemDuplicateReadTypeID handler:^(id opaqueItemData, BOOL * isDuplicate, BOOL * stop) {
Expand All @@ -1105,7 +1110,7 @@ - (void)_invokeCommandWithEndpointID:(NSNumber *)endpointID
completion:^(NSArray<NSDictionary<NSString *, id> *> * _Nullable values, NSError * _Nullable error) {
// Log the data at the INFO level (not usually persisted permanently),
// but make sure we log the work completion at the DEFAULT level.
MTR_LOG_INFO("Received command response: %@ error: %@", values, error);
MTR_LOG_INFO("Invoke work %tu received command response: %@ error: %@", workItemID, values, error);
dispatch_async(queue, ^{
completion(values, error);
});
Expand Down

0 comments on commit bd6d2c1

Please sign in to comment.