Skip to content

Commit

Permalink
Log the outgoing write values and command payloads in MTRDevice/MTRBa…
Browse files Browse the repository at this point in the history 
…seDevice. (#35699)
  • Loading branch information
@bzbarsky-apple
bzbarsky-apple authored Sep 21, 2024
1 parent 4842bfc commit 84ee115
Show file tree
Hide file tree
Showing 5 changed files with 79 additions and 30 deletions.
31 changes: 31 additions & 0 deletions src/darwin/Framework/CHIP/MTRBaseDevice.mm
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1000,6 +1000,8 @@ - (void)readAttributePaths:(NSArray<MTRAttributeRequestPath *> * _Nullable)attri
queue:(dispatch_queue_t)queue
completion:(MTRDeviceResponseHandler)completion
{
MTR_LOG("%@ readAttributePaths: %@, eventPaths: %@", self, attributePaths, eventPaths);

[self readAttributePaths:attributePaths eventPaths:eventPaths params:params includeDataVersion:NO queue:queue completion:completion];
}

Expand All @@ -1010,6 +1012,9 @@ - (void)readAttributePaths:(NSArray<MTRAttributeRequestPath *> * _Nullable)attri
queue:(dispatch_queue_t)queue
completion:(MTRDeviceResponseHandler)completion
{
// NOTE: Do not log the read here. This is called ether from
// readAttributePaths:eventPaths:params:queue:completion: or MTRDevice, both
// of which already log, and we want to be able to tell the two codepaths apart.
if ((attributePaths == nil || [attributePaths count] == 0) && (eventPaths == nil || [eventPaths count] == 0)) {
// No paths, just return an empty array.
dispatch_async(queue, ^{
Expand Down Expand Up @@ -1166,6 +1171,19 @@ - (void)writeAttributeWithEndpointID:(NSNumber *)endpointID
timedWriteTimeout:(NSNumber * _Nullable)timeoutMs
queue:(dispatch_queue_t)queue
completion:(MTRDeviceResponseHandler)completion
{
MTR_LOG("%@ write %@ 0x%llx 0x%llx: %@", self, endpointID, clusterID.unsignedLongLongValue, attributeID.unsignedLongLongValue, value);

[self _writeAttributeWithEndpointID:endpointID clusterID:clusterID attributeID:attributeID value:value timedWriteTimeout:timeoutMs queue:queue completion:completion];
}

- (void)_writeAttributeWithEndpointID:(NSNumber *)endpointID
clusterID:(NSNumber *)clusterID
attributeID:(NSNumber *)attributeID
value:(id)value
timedWriteTimeout:(NSNumber * _Nullable)timeoutMs
queue:(dispatch_queue_t)queue
completion:(MTRDeviceResponseHandler)completion
{
auto * bridge = new MTRDataValueDictionaryCallbackBridge(queue, completion,
^(ExchangeManager & exchangeManager, const SessionHandle & session, MTRDataValueDictionaryCallback successCb,
Expand Down Expand Up @@ -1346,6 +1364,7 @@ - (void)invokeCommandWithEndpointID:(NSNumber *)endpointID
commandFields:commandFields
timedInvokeTimeout:timeoutMs
serverSideProcessingTimeout:nil
logCall:YES
queue:queue
completion:completion];
}
Expand All @@ -1356,6 +1375,7 @@ - (void)_invokeCommandWithEndpointID:(NSNumber *)endpointID
commandFields:(id)commandFields
timedInvokeTimeout:(NSNumber * _Nullable)timeoutMs
serverSideProcessingTimeout:(NSNumber * _Nullable)serverSideProcessingTimeout
logCall:(BOOL)logCall
queue:(dispatch_queue_t)queue
completion:(MTRDeviceResponseHandler)completion
{
Expand All @@ -1376,6 +1396,10 @@ - (void)_invokeCommandWithEndpointID:(NSNumber *)endpointID
timeoutMs = MTRClampedNumber(timeoutMs, @(1), @(UINT16_MAX));
}

if (logCall) {
MTR_LOG("%@ invoke %@ 0x%llx 0x%llx: %@", self, endpointID, clusterID.unsignedLongLongValue, commandID.unsignedLongLongValue, commandFields);
}

auto * bridge = new MTRDataValueDictionaryCallbackBridge(queue, completion,
^(ExchangeManager & exchangeManager, const SessionHandle & session, MTRDataValueDictionaryCallback successCb,
MTRErrorCallback failureCb, MTRCallbackBridgeBase * bridge) {
Expand Down Expand Up @@ -1499,6 +1523,7 @@ - (void)_invokeKnownCommandWithEndpointID:(NSNumber *)endpointID
commandFields:commandFields
timedInvokeTimeout:timeout
serverSideProcessingTimeout:serverSideProcessingTimeout
logCall:YES
queue:queue
completion:responseHandler];
}
Expand Down Expand Up @@ -2157,6 +2182,12 @@ - (void)downloadLogOfType:(MTRDiagnosticLogType)type
completion:completion];
}

- (NSString *)description
{
return [NSString
stringWithFormat:@"<%@: %p, node: %016llX-%016llX (%llu)>", NSStringFromClass(self.class), self, _deviceController.compressedFabricID.unsignedLongLongValue, _nodeID, _nodeID];
}

@end

@implementation MTRBaseDevice (Deprecated)
Expand Down
15 changes: 14 additions & 1 deletion src/darwin/Framework/CHIP/MTRBaseDevice_Internal.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -116,14 +116,16 @@ static inline MTRTransportType MTRMakeTransportType(chip::Transport::Type type)

/**
* Like the public invokeCommandWithEndpointID but allows passing through a
* serverSideProcessingTimeout.
* serverSideProcessingTimeout and controlling whether we log the call (so we
* can not log when the call is not actually originating with MTRBaseDevice).
*/
- (void)_invokeCommandWithEndpointID:(NSNumber *)endpointID
clusterID:(NSNumber *)clusterID
commandID:(NSNumber *)commandID
commandFields:(id)commandFields
timedInvokeTimeout:(NSNumber * _Nullable)timeoutMs
serverSideProcessingTimeout:(NSNumber * _Nullable)serverSideProcessingTimeout
logCall:(BOOL)logCall
queue:(dispatch_queue_t)queue
completion:(MTRDeviceResponseHandler)completion;

Expand Down Expand Up @@ -195,6 +197,17 @@ static inline MTRTransportType MTRMakeTransportType(chip::Transport::Type type)
queue:(dispatch_queue_t)queue
completion:(MTRDeviceResponseHandler)completion;

/**
* Same as the public version, except for logging. For use from MTRDevice only.
*/
- (void)_writeAttributeWithEndpointID:(NSNumber *)endpointID
clusterID:(NSNumber *)clusterID
attributeID:(NSNumber *)attributeID
value:(id)value
timedWriteTimeout:(NSNumber * _Nullable)timeoutMs
queue:(dispatch_queue_t)queue
completion:(MTRDeviceResponseHandler)completion;

@end

@interface MTRClusterPath ()
Expand Down
15 changes: 8 additions & 7 deletions src/darwin/Framework/CHIP/MTRDeviceOverXPC.mm
View file
Original file line number Diff line number Diff line change
Expand Up @@ -194,13 +194,13 @@ - (void)readAttributePaths:(NSArray<MTRAttributeRequestPath *> * _Nullable)attri
}
}

- (void)writeAttributeWithEndpointID:(NSNumber *)endpointID
clusterID:(NSNumber *)clusterID
attributeID:(NSNumber *)attributeID
value:(id)value
timedWriteTimeout:(NSNumber * _Nullable)timeoutMs
queue:(dispatch_queue_t)queue
completion:(MTRDeviceResponseHandler)completion
- (void)_writeAttributeWithEndpointID:(NSNumber *)endpointID
clusterID:(NSNumber *)clusterID
attributeID:(NSNumber *)attributeID
value:(id)value
timedWriteTimeout:(NSNumber * _Nullable)timeoutMs
queue:(dispatch_queue_t)queue
completion:(MTRDeviceResponseHandler)completion
{
MTR_LOG_DEBUG("Writing attribute ...");

Expand Down Expand Up @@ -276,6 +276,7 @@ - (void)_invokeCommandWithEndpointID:(NSNumber *)endpointID
commandFields:(id)commandFields
timedInvokeTimeout:(NSNumber * _Nullable)timeoutMs
serverSideProcessingTimeout:(NSNumber * _Nullable)serverSideProcessingTimeout
logCall:(BOOL)logCall
queue:(dispatch_queue_t)queue
completion:(MTRDeviceResponseHandler)completion
{
Expand Down
42 changes: 23 additions & 19 deletions src/darwin/Framework/CHIP/MTRDevice_Concrete.mm
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2862,6 +2862,8 @@ - (void)writeAttributeWithEndpointID:(NSNumber *)endpointID
expectedValueInterval:(NSNumber *)expectedValueInterval
timedWriteTimeout:(NSNumber * _Nullable)timeout
{
value = [value copy];

if (timeout) {
timeout = MTRClampedNumber(timeout, @(1), @(UINT16_MAX));
}
Expand Down Expand Up @@ -2901,7 +2903,7 @@ - (void)writeAttributeWithEndpointID:(NSNumber *)endpointID
// [ attribute path, value, timedWriteTimeout, expectedValueID ]
//
// where expectedValueID is stored as NSNumber and NSNull represents nil timeouts
auto * writeData = @[ attributePath, [value copy], timeout ?: [NSNull null], @(expectedValueID) ];
auto * writeData = @[ attributePath, value, timeout ?: [NSNull null], @(expectedValueID) ];

NSMutableArray<NSArray *> * writeRequests = [NSMutableArray arrayWithObject:writeData];

Expand Down Expand Up @@ -2958,24 +2960,24 @@ - (void)writeAttributeWithEndpointID:(NSNumber *)endpointID
}

[baseDevice
writeAttributeWithEndpointID:path.endpoint
clusterID:path.cluster
attributeID:path.attribute
value:request[MTRDeviceWriteRequestFieldValueIndex]
timedWriteTimeout:timedWriteTimeout
queue:self.queue
completion:^(NSArray<NSDictionary<NSString *, id> *> * _Nullable values, NSError * _Nullable error) {
if (error) {
MTR_LOG_ERROR("Write attribute work item [%llu] failed: %@", workItemID, error);
if (useValueAsExpectedValue) {
NSNumber * expectedValueID = request[MTRDeviceWriteRequestFieldExpectedValueIDIndex];
[self removeExpectedValueForAttributePath:attributePath expectedValueID:expectedValueID.unsignedLongLongValue];
}
}
completion(MTRAsyncWorkComplete);
}];
_writeAttributeWithEndpointID:path.endpoint
clusterID:path.cluster
attributeID:path.attribute
value:request[MTRDeviceWriteRequestFieldValueIndex]
timedWriteTimeout:timedWriteTimeout
queue:self.queue
completion:^(NSArray<NSDictionary<NSString *, id> *> * _Nullable values, NSError * _Nullable error) {
if (error) {
MTR_LOG_ERROR("Write attribute work item [%llu] failed: %@", workItemID, error);
if (useValueAsExpectedValue) {
NSNumber * expectedValueID = request[MTRDeviceWriteRequestFieldExpectedValueIDIndex];
[self removeExpectedValueForAttributePath:attributePath expectedValueID:expectedValueID.unsignedLongLongValue];
}
}
completion(MTRAsyncWorkComplete);
}];
}];
[_asyncWorkQueue enqueueWorkItem:workItem descriptionWithFormat:@"write %@ 0x%llx 0x%llx", endpointID, clusterID.unsignedLongLongValue, attributeID.unsignedLongLongValue];
[_asyncWorkQueue enqueueWorkItem:workItem descriptionWithFormat:@"write %@ 0x%llx 0x%llx: %@", endpointID, clusterID.unsignedLongLongValue, attributeID.unsignedLongLongValue, value];
}

- (NSArray<NSDictionary<NSString *, id> *> *)readAttributePaths:(NSArray<MTRAttributeRequestPath *> *)attributePaths
Expand Down Expand Up @@ -3045,6 +3047,7 @@ - (void)_invokeCommandWithEndpointID:(NSNumber *)endpointID

serverSideProcessingTimeout = [serverSideProcessingTimeout copy];
timeout = [timeout copy];
commandFields = [commandFields copy];

if (timeout == nil && MTRCommandNeedsTimedInvoke(clusterID, commandID)) {
timeout = @(MTR_DEFAULT_TIMED_INTERACTION_TIMEOUT_MS);
Expand Down Expand Up @@ -3105,6 +3108,7 @@ - (void)_invokeCommandWithEndpointID:(NSNumber *)endpointID
commandFields:commandFields
timedInvokeTimeout:timedInvokeTimeout
serverSideProcessingTimeout:serverSideProcessingTimeout
logCall:NO
queue:self.queue
completion:^(NSArray<NSDictionary<NSString *, id> *> * _Nullable values, NSError * _Nullable error) {
// Log the data at the INFO level (not usually persisted permanently),
Expand All @@ -3120,7 +3124,7 @@ - (void)_invokeCommandWithEndpointID:(NSNumber *)endpointID
workDone(values, error);
}];
}];
[_asyncWorkQueue enqueueWorkItem:workItem descriptionWithFormat:@"invoke %@ 0x%llx 0x%llx", endpointID, clusterID.unsignedLongLongValue, commandID.unsignedLongLongValue];
[_asyncWorkQueue enqueueWorkItem:workItem descriptionWithFormat:@"invoke %@ 0x%llx 0x%llx: %@", endpointID, clusterID.unsignedLongLongValue, commandID.unsignedLongLongValue, commandFields];
}

- (void)openCommissioningWindowWithSetupPasscode:(NSNumber *)setupPasscode
Expand Down
6 changes: 3 additions & 3 deletions src/darwin/Framework/CHIP/MTRDiagnosticLogsDownloader.mm
View file
Original file line number Diff line number Diff line change
Expand Up @@ -446,15 +446,15 @@ - (void)downloadLogFromNodeWithID:(NSNumber *)nodeID
[download checkInteractionModelResponse:response error:error];
};

auto * device = [MTRBaseDevice deviceWithNodeID:nodeID controller:controller];
auto * cluster = [[MTRBaseClusterDiagnosticLogs alloc] initWithDevice:device endpointID:@(kDiagnosticLogsEndPoint) queue:queue];
auto * device = [MTRDevice deviceWithNodeID:nodeID controller:controller];
auto * cluster = [[MTRClusterDiagnosticLogs alloc] initWithDevice:device endpointID:@(kDiagnosticLogsEndPoint) queue:queue];

auto * params = [[MTRDiagnosticLogsClusterRetrieveLogsRequestParams alloc] init];
params.intent = @(type);
params.requestedProtocol = @(MTRDiagnosticLogsTransferProtocolBDX);
params.transferFileDesignator = download.fileDesignator;

[cluster retrieveLogsRequestWithParams:params completion:interactionModelDone];
[cluster retrieveLogsRequestWithParams:params expectedValues:nil expectedValueInterval:nil completion:interactionModelDone];

if (timeoutInSeconds > 0) {
auto err = _bridge->StartBDXTransferTimeout(download, timeoutInSeconds);
Expand Down

0 comments on commit 84ee115

Please sign in to comment.