Skip to content

Commit

Permalink
Darwin changes for logging (#32053)
Browse files Browse the repository at this point in the history
  • Loading branch information
@woody-apple
woody-apple authored Feb 14, 2024
1 parent 67f2ae5 commit a95c3d5
Show file tree
Hide file tree
Showing 9 changed files with 65 additions and 53 deletions.
39 changes: 23 additions & 16 deletions src/darwin/Framework/CHIP/MTRDevice.mm
View file
Original file line number Diff line number Diff line change
Expand Up @@ -284,6 +284,8 @@ - (void)invalidate

os_unfair_lock_lock(&self->_lock);

_state = MTRDeviceStateUnknown;

_weakDelegate = nil;

// Make sure we don't try to resubscribe if we have a pending resubscribe
Expand Down Expand Up @@ -343,20 +345,23 @@ - (void)_changeState:(MTRDeviceState)state
_state = state;
if (lastState != state) {
if (state != MTRDeviceStateReachable) {
MTR_LOG_INFO("%@ State change %lu => %lu, set estimated start time to nil", self, static_cast<unsigned long>(lastState),
MTR_LOG_INFO("%@ reachability state change %lu => %lu, set estimated start time to nil", self, static_cast<unsigned long>(lastState),
static_cast<unsigned long>(state));
_estimatedStartTime = nil;
_estimatedStartTimeFromGeneralDiagnosticsUpTime = nil;
} else {
MTR_LOG_INFO(
"%@ State change %lu => %lu", self, static_cast<unsigned long>(lastState), static_cast<unsigned long>(state));
"%@ reachability state change %lu => %lu", self, static_cast<unsigned long>(lastState), static_cast<unsigned long>(state));
}
id<MTRDeviceDelegate> delegate = _weakDelegate.strongObject;
if (delegate) {
dispatch_async(_delegateQueue, ^{
[delegate device:self stateChanged:state];
});
}
} else {
MTR_LOG_INFO(
"%@ Not reporting reachability state change, since no change in state %lu => %lu", self, static_cast<unsigned long>(lastState), static_cast<unsigned long>(state));
}
}

Expand Down Expand Up @@ -592,14 +597,14 @@ - (void)_handleEventReport:(NSArray<NSDictionary<NSString *, id> *> *)eventRepor
// If event time is of MTREventTimeTypeSystemUpTime type, then update estimated start time as needed
NSNumber * eventTimeTypeNumber = eventDict[MTREventTimeTypeKey];
if (!eventTimeTypeNumber) {
MTR_LOG_ERROR("Event %@ missing event time type", eventDict);
MTR_LOG_ERROR("%@ Event %@ missing event time type", self, eventDict);
continue;
}
MTREventTimeType eventTimeType = (MTREventTimeType) eventTimeTypeNumber.unsignedIntegerValue;
if (eventTimeType == MTREventTimeTypeSystemUpTime) {
NSNumber * eventTimeValueNumber = eventDict[MTREventSystemUpTimeKey];
if (!eventTimeValueNumber) {
MTR_LOG_ERROR("Event %@ missing event time value", eventDict);
MTR_LOG_ERROR("%@ Event %@ missing event time value", self, eventDict);
continue;
}
NSTimeInterval eventTimeValue = eventTimeValueNumber.doubleValue;
Expand Down Expand Up @@ -792,7 +797,7 @@ - (void)_setupSubscription
CHIP_ERROR err = readClient->SendAutoResubscribeRequest(std::move(readParams));

if (err != CHIP_NO_ERROR) {
NSError * error = [MTRError errorForCHIPErrorCode:err];
NSError * error = [MTRError errorForCHIPErrorCode:err logContext:self];
MTR_LOG_ERROR("%@ SendAutoResubscribeRequest error %@", self, error);
dispatch_async(self.queue, ^{
[self _handleSubscriptionError:error];
Expand Down Expand Up @@ -982,6 +987,8 @@ 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];
uint64_t workItemID = workItem.uniqueID; // capture only the ID, not the work item
NSNumber * nodeID = [self nodeID];

[workItem setBatchingID:MTRDeviceWorkItemBatchingReadID data:readRequests handler:^(id opaqueDataCurrent, id opaqueDataNext) {
mtr_hide(self); // don't capture self accidentally
NSMutableArray<NSArray *> * readRequestsCurrent = opaqueDataCurrent;
Expand All @@ -991,23 +998,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 read attribute work item [%llu]: cannot add more work, item is full", workItemID);
MTR_LOG_INFO("Batching read attribute work item [%llu]: cannot add more work, item is full [%@:%@:%@:%@]", workItemID, nodeID, endpointID, clusterID, attributeID);
return outcome;
}

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

// merge the next item's first request into the current item's list
auto readItem = readRequestsNext.firstObject;
[readRequestsNext removeObjectAtIndex:0];
[readRequestsCurrent addObject:readItem];
MTR_LOG_INFO("Batching read attribute work item [%llu]: added %@ (now %tu requests total)",
workItemID, readItem, readRequestsCurrent.count);
MTR_LOG_INFO("Batching read attribute work item [%llu]: added %@ (now %tu requests total) [%@:%@:%@:%@]",
workItemID, readItem, readRequestsCurrent.count, nodeID, endpointID, clusterID, attributeID);
outcome = MTRBatchedPartially;
}
NSCAssert(readRequestsNext.count == 0, @"should have batched everything or returned early");
Expand All @@ -1017,7 +1024,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 work item [%llu] report duplicate %@", workItemID, readItem);
MTR_LOG_DEFAULT("Read attribute work item [%llu] report duplicate %@ [%@:%@:%@:%@]", workItemID, readItem, nodeID, endpointID, clusterID, attributeID);
*isDuplicate = YES;
*stop = YES;
return;
Expand Down Expand Up @@ -1053,23 +1060,23 @@ 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 work item [%llu] result: %@", workItemID, values);
MTR_LOG_INFO("Read attribute work item [%llu] result: %@ [%@:%@:%@:%@]", workItemID, values, nodeID, endpointID, clusterID, attributeID);
[self _handleAttributeReport:values];
}

// TODO: better retry logic
if (error && (retryCount < 2)) {
MTR_LOG_ERROR("Read attribute work item [%llu] failed (will retry): %@", workItemID, error);
MTR_LOG_ERROR("Read attribute work item [%llu] failed (will retry): %@ [%@:%@:%@:%@]", workItemID, error, nodeID, endpointID, clusterID, attributeID);
completion(MTRAsyncWorkNeedsRetry);
} else {
if (error) {
MTR_LOG_DEFAULT("Read attribute work item [%llu] failed (giving up): %@", workItemID, error);
MTR_LOG_DEFAULT("Read attribute work item [%llu] failed (giving up): %@ [%@:%@:%@:%@]", workItemID, error, nodeID, endpointID, clusterID, attributeID);
}
completion(MTRAsyncWorkComplete);
}
}];
}];
[_asyncWorkQueue enqueueWorkItem:workItem descriptionWithFormat:@"read %@ %@ %@", endpointID, clusterID, attributeID];
[_asyncWorkQueue enqueueWorkItem:workItem descriptionWithFormat:@"read %@ %@ %@ %@", self.nodeID, endpointID, clusterID, attributeID];
}

return attributeValueToReturn;
Expand Down Expand Up @@ -1137,7 +1144,7 @@ - (void)writeAttributeWithEndpointID:(NSNumber *)endpointID
completion(MTRAsyncWorkComplete);
}];
}];
[_asyncWorkQueue enqueueWorkItem:workItem descriptionWithFormat:@"write %@ %@ %@", endpointID, clusterID, attributeID];
[_asyncWorkQueue enqueueWorkItem:workItem descriptionWithFormat:@"write %@ %@ %@ %@", self.nodeID, endpointID, clusterID, attributeID];
}

- (void)invokeCommandWithEndpointID:(NSNumber *)endpointID
Expand Down Expand Up @@ -1739,7 +1746,7 @@ - (void)setExpectedValues:(NSArray<NSDictionary<NSString *, id> *> *)values
NSDate * expirationTime = [NSDate dateWithTimeIntervalSinceNow:expectedValueInterval.doubleValue / 1000];

MTR_LOG_INFO(
"Setting expected values %@ with expiration time %f seconds from now", values, [expirationTime timeIntervalSinceNow]);
"%@ Setting expected values %@ with expiration time %f seconds from now", self, values, [expirationTime timeIntervalSinceNow]);

os_unfair_lock_lock(&self->_lock);

Expand Down
52 changes: 27 additions & 25 deletions src/darwin/Framework/CHIP/MTRError.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -104,31 +104,33 @@ typedef NS_ERROR_ENUM(MTRErrorDomain, MTRErrorCode){
typedef NS_ERROR_ENUM(MTRInteractionErrorDomain, MTRInteractionErrorCode){
// These values come from the general status code table in the Matter
// Interaction Model specification.
MTRInteractionErrorCodeFailure = 0x01,
MTRInteractionErrorCodeInvalidSubscription = 0x7d,
MTRInteractionErrorCodeUnsupportedAccess = 0x7e,
MTRInteractionErrorCodeUnsupportedEndpoint = 0x7f,
MTRInteractionErrorCodeInvalidAction = 0x80,
MTRInteractionErrorCodeUnsupportedCommand = 0x81,
MTRInteractionErrorCodeInvalidCommand = 0x85,
MTRInteractionErrorCodeUnsupportedAttribute = 0x86,
MTRInteractionErrorCodeConstraintError = 0x87,
MTRInteractionErrorCodeUnsupportedWrite = 0x88,
MTRInteractionErrorCodeResourceExhausted = 0x89,
MTRInteractionErrorCodeNotFound = 0x8b,
MTRInteractionErrorCodeUnreportableAttribute = 0x8c,
MTRInteractionErrorCodeInvalidDataType = 0x8d,
MTRInteractionErrorCodeUnsupportedRead = 0x8f,
MTRInteractionErrorCodeDataVersionMismatch = 0x92,
MTRInteractionErrorCodeTimeout = 0x94,
MTRInteractionErrorCodeBusy = 0x9c,
MTRInteractionErrorCodeUnsupportedCluster = 0xc3,
MTRInteractionErrorCodeNoUpstreamSubscription = 0xc5,
MTRInteractionErrorCodeNeedsTimedInteraction = 0xc6,
MTRInteractionErrorCodeUnsupportedEvent = 0xc7,
MTRInteractionErrorCodePathsExhausted = 0xc8,
MTRInteractionErrorCodeTimedRequestMismatch = 0xc9,
MTRInteractionErrorCodeFailsafeRequired = 0xca,
MTRInteractionErrorCodeFailure = 0x01,
MTRInteractionErrorCodeInvalidSubscription = 0x7d,
MTRInteractionErrorCodeUnsupportedAccess = 0x7e,
MTRInteractionErrorCodeUnsupportedEndpoint = 0x7f,
MTRInteractionErrorCodeInvalidAction = 0x80,
MTRInteractionErrorCodeUnsupportedCommand = 0x81,
MTRInteractionErrorCodeInvalidCommand = 0x85,
MTRInteractionErrorCodeUnsupportedAttribute = 0x86,
MTRInteractionErrorCodeConstraintError = 0x87,
MTRInteractionErrorCodeUnsupportedWrite = 0x88,
MTRInteractionErrorCodeResourceExhausted = 0x89,
MTRInteractionErrorCodeNotFound = 0x8b,
MTRInteractionErrorCodeUnreportableAttribute = 0x8c,
MTRInteractionErrorCodeInvalidDataType = 0x8d,
MTRInteractionErrorCodeUnsupportedRead = 0x8f,
MTRInteractionErrorCodeDataVersionMismatch = 0x92,
MTRInteractionErrorCodeTimeout = 0x94,
MTRInteractionErrorCodeBusy = 0x9c,
MTRInteractionErrorCodeUnsupportedCluster = 0xc3,
MTRInteractionErrorCodeNoUpstreamSubscription = 0xc5,
MTRInteractionErrorCodeNeedsTimedInteraction = 0xc6,
MTRInteractionErrorCodeUnsupportedEvent = 0xc7,
MTRInteractionErrorCodePathsExhausted = 0xc8,
MTRInteractionErrorCodeTimedRequestMismatch = 0xc9,
MTRInteractionErrorCodeFailsafeRequired = 0xca,
MTRInteractionErrorInvalidInState MTR_NEWLY_AVAILABLE = 0xcb,
MTRInteractionErrorNoCommandResponse MTR_NEWLY_AVAILABLE = 0xcc,
};
// clang-format on

Expand Down
7 changes: 6 additions & 1 deletion src/darwin/Framework/CHIP/MTRError.mm
View file
Original file line number Diff line number Diff line change
Expand Up @@ -44,12 +44,17 @@ - (instancetype)initWithError:(CHIP_ERROR)error;
@implementation MTRError

+ (NSError *)errorForCHIPErrorCode:(CHIP_ERROR)errorCode
{
return [MTRError errorForCHIPErrorCode:errorCode logContext:nil];
}

+ (NSError *)errorForCHIPErrorCode:(CHIP_ERROR)errorCode logContext:(id)contextToLog
{
if (errorCode == CHIP_NO_ERROR) {
return nil;
}

ChipLogError(Controller, "Creating NSError from %" CHIP_ERROR_FORMAT, errorCode.Format());
ChipLogError(Controller, "Creating NSError from %" CHIP_ERROR_FORMAT " (context: %@)", errorCode.Format(), contextToLog);

if (errorCode.IsIMStatus()) {
chip::app::StatusIB status(errorCode);
Expand Down
1 change: 1 addition & 0 deletions src/darwin/Framework/CHIP/MTRError_Internal.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -27,6 +27,7 @@ NS_ASSUME_NONNULL_BEGIN

@interface MTRError : NSObject
+ (NSError * _Nullable)errorForCHIPErrorCode:(CHIP_ERROR)errorCode;
+ (NSError * _Nullable)errorForCHIPErrorCode:(CHIP_ERROR)errorCode logContext:(id _Nullable)contextToLog;
+ (NSError * _Nullable)errorForIMStatus:(const chip::app::StatusIB &)status;
+ (NSError * _Nullable)errorForIMStatusCode:(chip::Protocols::InteractionModel::Status)status;
+ (CHIP_ERROR)errorToCHIPErrorCode:(NSError * _Nullable)error;
Expand Down
8 changes: 4 additions & 4 deletions src/darwin/Framework/CHIP/MTRSetupPayload.mm
View file
Original file line number Diff line number Diff line change
Expand Up @@ -235,7 +235,7 @@ + (MTRSetupPayload * _Nullable)setupPayloadWithOnboardingPayload:(NSString *)onb

if (!validPayload) {
if (error) {
*error = [MTRError errorForCHIPErrorCode:CHIP_ERROR_INVALID_ARGUMENT];
*error = [MTRError errorForCHIPErrorCode:CHIP_ERROR_INVALID_ARGUMENT logContext:onboardingPayload];
}
return nil;
}
Expand Down Expand Up @@ -336,23 +336,23 @@ - (NSString * _Nullable)qrCodeString:(NSError * __autoreleasing *)error
if (self.commissioningFlow == MTRCommissioningFlowInvalid) {
// No idea how to map this to the standard codes.
if (error != nil) {
*error = [MTRError errorForCHIPErrorCode:CHIP_ERROR_INCORRECT_STATE];
*error = [MTRError errorForCHIPErrorCode:CHIP_ERROR_INCORRECT_STATE logContext:@"invalid flow"];
}
return nil;
}

if (self.hasShortDiscriminator) {
// Can't create a QR code with a short discriminator.
if (error != nil) {
*error = [MTRError errorForCHIPErrorCode:CHIP_ERROR_INCORRECT_STATE];
*error = [MTRError errorForCHIPErrorCode:CHIP_ERROR_INCORRECT_STATE logContext:@"cannot create a QR code with a short descrimintor"];
}
return nil;
}

if (self.discoveryCapabilities == MTRDiscoveryCapabilitiesUnknown) {
// Can't create a QR code if we don't know the discovery capabilities.
if (error != nil) {
*error = [MTRError errorForCHIPErrorCode:CHIP_ERROR_INCORRECT_STATE];
*error = [MTRError errorForCHIPErrorCode:CHIP_ERROR_INCORRECT_STATE logContext:@"cannot create a QR code with unknown discovery capabilities"];
}
return nil;
}
Expand Down
2 changes: 1 addition & 1 deletion src/darwin/Framework/Matter.xcodeproj/project.pbxproj
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1648,7 +1648,7 @@
isa = PBXProject;
attributes = {
BuildIndependentTargetsInParallel = YES;
LastUpgradeCheck = 1140;
LastUpgradeCheck = 1500;
ORGANIZATIONNAME = CHIP;
TargetAttributes = {
037C3CA42991A44B00B7EEE2 = {
Expand Down
4 changes: 1 addition & 3 deletions src/darwin/Framework/Matter.xcodeproj/xcshareddata/xcschemes/Matter Framework Tests.xcscheme
View file
Original file line number Diff line number Diff line change
@@ -1,6 +1,6 @@
<?xml version="1.0" encoding="UTF-8"?>
<Scheme
LastUpgradeVersion = "1200"
LastUpgradeVersion = "1500"
version = "1.7">
<BuildAction
parallelizeBuildables = "YES"
Expand Down Expand Up @@ -38,8 +38,6 @@
BlueprintName = "MatterTests"
ReferencedContainer = "container:Matter.xcodeproj">
</BuildableReference>
<SkippedTests>
</SkippedTests>
</TestableReference>
</Testables>
</TestAction>
Expand Down
2 changes: 1 addition & 1 deletion src/darwin/Framework/Matter.xcodeproj/xcshareddata/xcschemes/Matter Framework.xcscheme
View file
Original file line number Diff line number Diff line change
@@ -1,6 +1,6 @@
<?xml version="1.0" encoding="UTF-8"?>
<Scheme
LastUpgradeVersion = "1200"
LastUpgradeVersion = "1500"
version = "1.7">
<BuildAction
parallelizeBuildables = "YES"
Expand Down
3 changes: 1 addition & 2 deletions src/darwin/Framework/Matter.xcodeproj/xcshareddata/xcschemes/darwin-framework-tool.xcscheme
View file
Original file line number Diff line number Diff line change
@@ -1,6 +1,6 @@
<?xml version="1.0" encoding="UTF-8"?>
<Scheme
LastUpgradeVersion = "1410"
LastUpgradeVersion = "1500"
version = "1.7">
<BuildAction
parallelizeBuildables = "YES"
Expand Down Expand Up @@ -38,7 +38,6 @@
useCustomWorkingDirectory = "NO"
ignoresPersistentStateOnLaunch = "NO"
debugDocumentVersioning = "YES"
debugServiceExtension = ""
allowLocationSimulation = "YES"
viewDebuggingEnabled = "No">
<BuildableProductRunnable
Expand Down

0 comments on commit a95c3d5

Please sign in to comment.