From 84ee1156f085fae3e5efda4e935225f0a7d39f89 Mon Sep 17 00:00:00 2001 From: Boris Zbarsky Date: Sat, 21 Sep 2024 01:57:27 -0400 Subject: [PATCH] Log the outgoing write values and command payloads in MTRDevice/MTRBaseDevice. (#35699) --- src/darwin/Framework/CHIP/MTRBaseDevice.mm | 31 ++++++++++++++ .../Framework/CHIP/MTRBaseDevice_Internal.h | 15 ++++++- src/darwin/Framework/CHIP/MTRDeviceOverXPC.mm | 15 +++---- .../Framework/CHIP/MTRDevice_Concrete.mm | 42 ++++++++++--------- .../CHIP/MTRDiagnosticLogsDownloader.mm | 6 +-- 5 files changed, 79 insertions(+), 30 deletions(-) diff --git a/src/darwin/Framework/CHIP/MTRBaseDevice.mm b/src/darwin/Framework/CHIP/MTRBaseDevice.mm index 8c4b20a7daf915..0e0f960be1d2df 100644 --- a/src/darwin/Framework/CHIP/MTRBaseDevice.mm +++ b/src/darwin/Framework/CHIP/MTRBaseDevice.mm @@ -1000,6 +1000,8 @@ - (void)readAttributePaths:(NSArray * _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]; } @@ -1010,6 +1012,9 @@ - (void)readAttributePaths:(NSArray * _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, ^{ @@ -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, @@ -1346,6 +1364,7 @@ - (void)invokeCommandWithEndpointID:(NSNumber *)endpointID commandFields:commandFields timedInvokeTimeout:timeoutMs serverSideProcessingTimeout:nil + logCall:YES queue:queue completion:completion]; } @@ -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 { @@ -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) { @@ -1499,6 +1523,7 @@ - (void)_invokeKnownCommandWithEndpointID:(NSNumber *)endpointID commandFields:commandFields timedInvokeTimeout:timeout serverSideProcessingTimeout:serverSideProcessingTimeout + logCall:YES queue:queue completion:responseHandler]; } @@ -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) diff --git a/src/darwin/Framework/CHIP/MTRBaseDevice_Internal.h b/src/darwin/Framework/CHIP/MTRBaseDevice_Internal.h index 4ebc454925a4a4..1482d80634da43 100644 --- a/src/darwin/Framework/CHIP/MTRBaseDevice_Internal.h +++ b/src/darwin/Framework/CHIP/MTRBaseDevice_Internal.h @@ -116,7 +116,8 @@ 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 @@ -124,6 +125,7 @@ static inline MTRTransportType MTRMakeTransportType(chip::Transport::Type type) commandFields:(id)commandFields timedInvokeTimeout:(NSNumber * _Nullable)timeoutMs serverSideProcessingTimeout:(NSNumber * _Nullable)serverSideProcessingTimeout + logCall:(BOOL)logCall queue:(dispatch_queue_t)queue completion:(MTRDeviceResponseHandler)completion; @@ -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 () diff --git a/src/darwin/Framework/CHIP/MTRDeviceOverXPC.mm b/src/darwin/Framework/CHIP/MTRDeviceOverXPC.mm index 00b69d5899842a..a072134b205fde 100644 --- a/src/darwin/Framework/CHIP/MTRDeviceOverXPC.mm +++ b/src/darwin/Framework/CHIP/MTRDeviceOverXPC.mm @@ -194,13 +194,13 @@ - (void)readAttributePaths:(NSArray * _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 ..."); @@ -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 { diff --git a/src/darwin/Framework/CHIP/MTRDevice_Concrete.mm b/src/darwin/Framework/CHIP/MTRDevice_Concrete.mm index bc26905d174834..4617a78b161a2a 100644 --- a/src/darwin/Framework/CHIP/MTRDevice_Concrete.mm +++ b/src/darwin/Framework/CHIP/MTRDevice_Concrete.mm @@ -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)); } @@ -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 * writeRequests = [NSMutableArray arrayWithObject:writeData]; @@ -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 *> * _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 *> * _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 *> *)readAttributePaths:(NSArray *)attributePaths @@ -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); @@ -3105,6 +3108,7 @@ - (void)_invokeCommandWithEndpointID:(NSNumber *)endpointID commandFields:commandFields timedInvokeTimeout:timedInvokeTimeout serverSideProcessingTimeout:serverSideProcessingTimeout + logCall:NO queue:self.queue completion:^(NSArray *> * _Nullable values, NSError * _Nullable error) { // Log the data at the INFO level (not usually persisted permanently), @@ -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 diff --git a/src/darwin/Framework/CHIP/MTRDiagnosticLogsDownloader.mm b/src/darwin/Framework/CHIP/MTRDiagnosticLogsDownloader.mm index 69dfb86d1da40f..c461737cf504a8 100644 --- a/src/darwin/Framework/CHIP/MTRDiagnosticLogsDownloader.mm +++ b/src/darwin/Framework/CHIP/MTRDiagnosticLogsDownloader.mm @@ -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);