Skip to content

Commit bc45d9e

Browse files
bzbarsky-applebzbarsky-apple
committed
Log the outgoing write values and command payloads in MTRDevice/MTRBaseDevice.
1 parent 7b8467b commit bc45d9e

5 files changed

+79
-30
lines changed

‎src/darwin/Framework/CHIP/MTRBaseDevice.mm

+31
Original file line numberDiff line numberDiff line change
@@ -991,6 +991,8 @@ - (void)readAttributePaths:(NSArray<MTRAttributeRequestPath *> * _Nullable)attri
991991
queue:(dispatch_queue_t)queue
992992
completion:(MTRDeviceResponseHandler)completion
993993
{
994+
MTR_LOG("%@ readAttributePaths: %@, eventPaths: %@", self, attributePaths, eventPaths);
995+
994996
[self readAttributePaths:attributePaths eventPaths:eventPaths params:params includeDataVersion:NO queue:queue completion:completion];
995997
}
996998

@@ -1001,6 +1003,9 @@ - (void)readAttributePaths:(NSArray<MTRAttributeRequestPath *> * _Nullable)attri
10011003
queue:(dispatch_queue_t)queue
10021004
completion:(MTRDeviceResponseHandler)completion
10031005
{
1006+
// NOTE: Do not log the read here. This is called ether from
1007+
// readAttributePaths:eventPaths:params:queue:completion: or MTRDevice, both
1008+
// of which already log, and we want to be able to tell the two codepaths apart.
10041009
if ((attributePaths == nil || [attributePaths count] == 0) && (eventPaths == nil || [eventPaths count] == 0)) {
10051010
// No paths, just return an empty array.
10061011
dispatch_async(queue, ^{
@@ -1157,6 +1162,19 @@ - (void)writeAttributeWithEndpointID:(NSNumber *)endpointID
11571162
timedWriteTimeout:(NSNumber * _Nullable)timeoutMs
11581163
queue:(dispatch_queue_t)queue
11591164
completion:(MTRDeviceResponseHandler)completion
1165+
{
1166+
MTR_LOG("%@ write %@ 0x%llx 0x%llx: %@", self, endpointID, clusterID.unsignedLongLongValue, attributeID.unsignedLongLongValue, value);
1167+
1168+
[self _writeAttributeWithEndpointID:endpointID clusterID:clusterID attributeID:attributeID value:value timedWriteTimeout:timeoutMs queue:queue completion:completion];
1169+
}
1170+
1171+
- (void)_writeAttributeWithEndpointID:(NSNumber *)endpointID
1172+
clusterID:(NSNumber *)clusterID
1173+
attributeID:(NSNumber *)attributeID
1174+
value:(id)value
1175+
timedWriteTimeout:(NSNumber * _Nullable)timeoutMs
1176+
queue:(dispatch_queue_t)queue
1177+
completion:(MTRDeviceResponseHandler)completion
11601178
{
11611179
auto * bridge = new MTRDataValueDictionaryCallbackBridge(queue, completion,
11621180
^(ExchangeManager & exchangeManager, const SessionHandle & session, MTRDataValueDictionaryCallback successCb,
@@ -1337,6 +1355,7 @@ - (void)invokeCommandWithEndpointID:(NSNumber *)endpointID
13371355
commandFields:commandFields
13381356
timedInvokeTimeout:timeoutMs
13391357
serverSideProcessingTimeout:nil
1358+
logCall:YES
13401359
queue:queue
13411360
completion:completion];
13421361
}
@@ -1347,6 +1366,7 @@ - (void)_invokeCommandWithEndpointID:(NSNumber *)endpointID
13471366
commandFields:(id)commandFields
13481367
timedInvokeTimeout:(NSNumber * _Nullable)timeoutMs
13491368
serverSideProcessingTimeout:(NSNumber * _Nullable)serverSideProcessingTimeout
1369+
logCall:(BOOL)logCall
13501370
queue:(dispatch_queue_t)queue
13511371
completion:(MTRDeviceResponseHandler)completion
13521372
{
@@ -1367,6 +1387,10 @@ - (void)_invokeCommandWithEndpointID:(NSNumber *)endpointID
13671387
timeoutMs = MTRClampedNumber(timeoutMs, @(1), @(UINT16_MAX));
13681388
}
13691389

1390+
if (logCall) {
1391+
MTR_LOG("%@ invoke %@ 0x%llx 0x%llx: %@", self, endpointID, clusterID.unsignedLongLongValue, commandID.unsignedLongLongValue, commandFields);
1392+
}
1393+
13701394
auto * bridge = new MTRDataValueDictionaryCallbackBridge(queue, completion,
13711395
^(ExchangeManager & exchangeManager, const SessionHandle & session, MTRDataValueDictionaryCallback successCb,
13721396
MTRErrorCallback failureCb, MTRCallbackBridgeBase * bridge) {
@@ -1490,6 +1514,7 @@ - (void)_invokeKnownCommandWithEndpointID:(NSNumber *)endpointID
14901514
commandFields:commandFields
14911515
timedInvokeTimeout:timeout
14921516
serverSideProcessingTimeout:serverSideProcessingTimeout
1517+
logCall:YES
14931518
queue:queue
14941519
completion:responseHandler];
14951520
}
@@ -2148,6 +2173,12 @@ - (void)downloadLogOfType:(MTRDiagnosticLogType)type
21482173
completion:completion];
21492174
}
21502175

2176+
- (NSString *)description
2177+
{
2178+
return [NSString
2179+
stringWithFormat:@"<%@: %p, node: %016llX-%016llX (%llu)>", NSStringFromClass(self.class), self, _deviceController.compressedFabricID.unsignedLongLongValue, _nodeID, _nodeID];
2180+
}
2181+
21512182
@end
21522183

21532184
@implementation MTRBaseDevice (Deprecated)

‎src/darwin/Framework/CHIP/MTRBaseDevice_Internal.h

+14-1
Original file line numberDiff line numberDiff line change
@@ -116,14 +116,16 @@ static inline MTRTransportType MTRMakeTransportType(chip::Transport::Type type)
116116

117117
/**
118118
* Like the public invokeCommandWithEndpointID but allows passing through a
119-
* serverSideProcessingTimeout.
119+
* serverSideProcessingTimeout and controlling whether we log the call (so we
120+
* can not log when the call is not actually originating with MTRBaseDevice).
120121
*/
121122
- (void)_invokeCommandWithEndpointID:(NSNumber *)endpointID
122123
clusterID:(NSNumber *)clusterID
123124
commandID:(NSNumber *)commandID
124125
commandFields:(id)commandFields
125126
timedInvokeTimeout:(NSNumber * _Nullable)timeoutMs
126127
serverSideProcessingTimeout:(NSNumber * _Nullable)serverSideProcessingTimeout
128+
logCall:(BOOL)logCall
127129
queue:(dispatch_queue_t)queue
128130
completion:(MTRDeviceResponseHandler)completion;
129131

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

200+
/**
201+
* Same as the public version, except for logging. For use from MTRDevice only.
202+
*/
203+
- (void)_writeAttributeWithEndpointID:(NSNumber *)endpointID
204+
clusterID:(NSNumber *)clusterID
205+
attributeID:(NSNumber *)attributeID
206+
value:(id)value
207+
timedWriteTimeout:(NSNumber * _Nullable)timeoutMs
208+
queue:(dispatch_queue_t)queue
209+
completion:(MTRDeviceResponseHandler)completion;
210+
198211
@end
199212

200213
@interface MTRClusterPath ()

‎src/darwin/Framework/CHIP/MTRDeviceOverXPC.mm

+8-7
Original file line numberDiff line numberDiff line change
@@ -194,13 +194,13 @@ - (void)readAttributePaths:(NSArray<MTRAttributeRequestPath *> * _Nullable)attri
194194
}
195195
}
196196

197-
- (void)writeAttributeWithEndpointID:(NSNumber *)endpointID
198-
clusterID:(NSNumber *)clusterID
199-
attributeID:(NSNumber *)attributeID
200-
value:(id)value
201-
timedWriteTimeout:(NSNumber * _Nullable)timeoutMs
202-
queue:(dispatch_queue_t)queue
203-
completion:(MTRDeviceResponseHandler)completion
197+
- (void)_writeAttributeWithEndpointID:(NSNumber *)endpointID
198+
clusterID:(NSNumber *)clusterID
199+
attributeID:(NSNumber *)attributeID
200+
value:(id)value
201+
timedWriteTimeout:(NSNumber * _Nullable)timeoutMs
202+
queue:(dispatch_queue_t)queue
203+
completion:(MTRDeviceResponseHandler)completion
204204
{
205205
MTR_LOG_DEBUG("Writing attribute ...");
206206

@@ -276,6 +276,7 @@ - (void)_invokeCommandWithEndpointID:(NSNumber *)endpointID
276276
commandFields:(id)commandFields
277277
timedInvokeTimeout:(NSNumber * _Nullable)timeoutMs
278278
serverSideProcessingTimeout:(NSNumber * _Nullable)serverSideProcessingTimeout
279+
logCall:(BOOL)logCall
279280
queue:(dispatch_queue_t)queue
280281
completion:(MTRDeviceResponseHandler)completion
281282
{

‎src/darwin/Framework/CHIP/MTRDevice_Concrete.mm

+23-19
Original file line numberDiff line numberDiff line change
@@ -2862,6 +2862,8 @@ - (void)writeAttributeWithEndpointID:(NSNumber *)endpointID
28622862
expectedValueInterval:(NSNumber *)expectedValueInterval
28632863
timedWriteTimeout:(NSNumber * _Nullable)timeout
28642864
{
2865+
value = [value copy];
2866+
28652867
if (timeout) {
28662868
timeout = MTRClampedNumber(timeout, @(1), @(UINT16_MAX));
28672869
}
@@ -2901,7 +2903,7 @@ - (void)writeAttributeWithEndpointID:(NSNumber *)endpointID
29012903
// [ attribute path, value, timedWriteTimeout, expectedValueID ]
29022904
//
29032905
// where expectedValueID is stored as NSNumber and NSNull represents nil timeouts
2904-
auto * writeData = @[ attributePath, [value copy], timeout ?: [NSNull null], @(expectedValueID) ];
2906+
auto * writeData = @[ attributePath, value, timeout ?: [NSNull null], @(expectedValueID) ];
29052907

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

@@ -2958,24 +2960,24 @@ - (void)writeAttributeWithEndpointID:(NSNumber *)endpointID
29582960
}
29592961

29602962
[baseDevice
2961-
writeAttributeWithEndpointID:path.endpoint
2962-
clusterID:path.cluster
2963-
attributeID:path.attribute
2964-
value:request[MTRDeviceWriteRequestFieldValueIndex]
2965-
timedWriteTimeout:timedWriteTimeout
2966-
queue:self.queue
2967-
completion:^(NSArray<NSDictionary<NSString *, id> *> * _Nullable values, NSError * _Nullable error) {
2968-
if (error) {
2969-
MTR_LOG_ERROR("Write attribute work item [%llu] failed: %@", workItemID, error);
2970-
if (useValueAsExpectedValue) {
2971-
NSNumber * expectedValueID = request[MTRDeviceWriteRequestFieldExpectedValueIDIndex];
2972-
[self removeExpectedValueForAttributePath:attributePath expectedValueID:expectedValueID.unsignedLongLongValue];
2973-
}
2974-
}
2975-
completion(MTRAsyncWorkComplete);
2976-
}];
2963+
_writeAttributeWithEndpointID:path.endpoint
2964+
clusterID:path.cluster
2965+
attributeID:path.attribute
2966+
value:request[MTRDeviceWriteRequestFieldValueIndex]
2967+
timedWriteTimeout:timedWriteTimeout
2968+
queue:self.queue
2969+
completion:^(NSArray<NSDictionary<NSString *, id> *> * _Nullable values, NSError * _Nullable error) {
2970+
if (error) {
2971+
MTR_LOG_ERROR("Write attribute work item [%llu] failed: %@", workItemID, error);
2972+
if (useValueAsExpectedValue) {
2973+
NSNumber * expectedValueID = request[MTRDeviceWriteRequestFieldExpectedValueIDIndex];
2974+
[self removeExpectedValueForAttributePath:attributePath expectedValueID:expectedValueID.unsignedLongLongValue];
2975+
}
2976+
}
2977+
completion(MTRAsyncWorkComplete);
2978+
}];
29772979
}];
2978-
[_asyncWorkQueue enqueueWorkItem:workItem descriptionWithFormat:@"write %@ 0x%llx 0x%llx", endpointID, clusterID.unsignedLongLongValue, attributeID.unsignedLongLongValue];
2980+
[_asyncWorkQueue enqueueWorkItem:workItem descriptionWithFormat:@"write %@ 0x%llx 0x%llx: %@", endpointID, clusterID.unsignedLongLongValue, attributeID.unsignedLongLongValue, value];
29792981
}
29802982

29812983
- (NSArray<NSDictionary<NSString *, id> *> *)readAttributePaths:(NSArray<MTRAttributeRequestPath *> *)attributePaths
@@ -3070,6 +3072,7 @@ - (void)_invokeCommandWithEndpointID:(NSNumber *)endpointID
30703072

30713073
serverSideProcessingTimeout = [serverSideProcessingTimeout copy];
30723074
timeout = [timeout copy];
3075+
commandFields = [commandFields copy];
30733076

30743077
if (timeout == nil && MTRCommandNeedsTimedInvoke(clusterID, commandID)) {
30753078
timeout = @(MTR_DEFAULT_TIMED_INTERACTION_TIMEOUT_MS);
@@ -3130,6 +3133,7 @@ - (void)_invokeCommandWithEndpointID:(NSNumber *)endpointID
31303133
commandFields:commandFields
31313134
timedInvokeTimeout:timedInvokeTimeout
31323135
serverSideProcessingTimeout:serverSideProcessingTimeout
3136+
logCall:NO
31333137
queue:self.queue
31343138
completion:^(NSArray<NSDictionary<NSString *, id> *> * _Nullable values, NSError * _Nullable error) {
31353139
// Log the data at the INFO level (not usually persisted permanently),
@@ -3145,7 +3149,7 @@ - (void)_invokeCommandWithEndpointID:(NSNumber *)endpointID
31453149
workDone(values, error);
31463150
}];
31473151
}];
3148-
[_asyncWorkQueue enqueueWorkItem:workItem descriptionWithFormat:@"invoke %@ 0x%llx 0x%llx", endpointID, clusterID.unsignedLongLongValue, commandID.unsignedLongLongValue];
3152+
[_asyncWorkQueue enqueueWorkItem:workItem descriptionWithFormat:@"invoke %@ 0x%llx 0x%llx: %@", endpointID, clusterID.unsignedLongLongValue, commandID.unsignedLongLongValue, commandFields];
31493153
}
31503154

31513155
- (void)openCommissioningWindowWithSetupPasscode:(NSNumber *)setupPasscode

‎src/darwin/Framework/CHIP/MTRDiagnosticLogsDownloader.mm

+3-3
Original file line numberDiff line numberDiff line change
@@ -446,15 +446,15 @@ - (void)downloadLogFromNodeWithID:(NSNumber *)nodeID
446446
[download checkInteractionModelResponse:response error:error];
447447
};
448448

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

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

457-
[cluster retrieveLogsRequestWithParams:params completion:interactionModelDone];
457+
[cluster retrieveLogsRequestWithParams:params expectedValues:nil expectedValueInterval:nil completion:interactionModelDone];
458458

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

0 commit comments

Comments
 (0)