[Diagnostic Logs] Followup for project-chip#31638 (project-chip#31833)

* [CI] Make it possible to specify the timeout when waiting for a specific string in scripts/tests/chiptest/test_definition.py since it may be longer than 10 seconds

* [CI] Add a second instance of the configured applications such that YAML can start the app multiple times if needed

* [BDX:DiagnosticLog] Update the server such that it supports multiple downloads in parallel

* [darwin-framework-tool] Address post-landing comments of project-chip#31638

[CI] Add some tests for bdx download with darwin-framework-tool

Author: vivien-apple

examples/chip-tool/py_matter_chip_tool_adapter/matter_chip_tool_adapter/encoder.py

@@ -148,6 +148,17 @@
         }
     },
 
+    'Bdx': {
+        'commands': {
+            'Download': {
+                'arguments': {
+                    'LogType': 'log-type',
+                },
+                'has_endpoint': False,
+            }
+        }
+    },
+
     'DelayCommands': {
         'alias': 'delay',
         'commands': {

examples/darwin-framework-tool/commands/bdx/DownloadLogCommand.h

@@ -32,14 +32,23 @@ class DownloadLogCommand : public CHIPCommandBridge
                     "The timeout for getting the log. If the timeout expires, completion will be called with whatever has been "
                     "retrieved by that point (which might be none or a partial log). If the timeout is set to 0, the request will "
                     "not expire and completion will not be called until the log is fully retrieved or an error occurs.");
+        AddArgument("async", 0, 1, &mIsAsyncCommand,
+                    "By default the command waits for the download to finish before returning. If async is true the command will "
+                    "not wait and the download will proceed in the background");
+        AddArgument("filepath", &mFilePath, "An optional filepath to save the download log content to.");
     }
 
     /////////// CHIPCommandBridge Interface /////////
     CHIP_ERROR RunCommand() override;
-    chip::System::Clock::Timeout GetWaitDuration() const override { return chip::System::Clock::Seconds16(10); }
+    chip::System::Clock::Timeout GetWaitDuration() const override
+    {
+        return chip::System::Clock::Seconds16(mTimeout > 0 ? mTimeout + 10 : 300);
+    }
 
 private:
     chip::NodeId mNodeId;
     uint8_t mLogType;
     uint16_t mTimeout;
+    chip::Optional<char *> mFilePath;
+    chip::Optional<bool> mIsAsyncCommand;
 };

examples/darwin-framework-tool/commands/bdx/DownloadLogCommand.mm

@@ -21,6 +21,7 @@
 #import "MTRError_Utils.h"
 
 #include "DownloadLogCommand.h"
+#include "RemoteDataModelLogger.h"
 
 CHIP_ERROR DownloadLogCommand::RunCommand()
 {
@@ -32,27 +33,62 @@
     auto logType = static_cast<MTRDiagnosticLogType>(mLogType);
     auto queue = dispatch_queue_create("com.chip.bdx.downloader", DISPATCH_QUEUE_SERIAL);
 
+    bool shouldWaitForDownload = !mIsAsyncCommand.ValueOr(false);
+    mIsAsyncCommand.ClearValue();
+
+    bool dumpToFile = mFilePath.HasValue();
+    auto * dumpFilePath = dumpToFile ? [NSString stringWithUTF8String:mFilePath.Value()] : nil;
+    mFilePath.ClearValue();
+
     auto * self = this;
     auto completion = ^(NSURL * url, NSError * error) {
         // A non-nil url indicates the presence of content, which can occur even in error scenarios like timeouts.
+        NSString * logContent = nil;
         if (nil != url) {
             NSError * readError = nil;
             auto * data = [NSData dataWithContentsOfURL:url options:NSDataReadingUncached error:&readError];
-            VerifyOrReturn(nil == readError, self->SetCommandExitStatus(MTRErrorToCHIPErrorCode(readError)));
+            if (nil != readError) {
+                if (shouldWaitForDownload) {
+                    self->SetCommandExitStatus(MTRErrorToCHIPErrorCode(readError));
+                }
+                return;
+            }
+
+            logContent = [[NSString alloc] initWithData:data encoding:NSUTF8StringEncoding];
+            NSLog(@"Content: %@", logContent);
 
-            auto * content = [[NSString alloc] initWithData:data encoding:NSUTF8StringEncoding];
-            NSLog(@"Content: %@", content);
+            if (dumpToFile) {
+                NSError * writeError = nil;
+                auto * fileManager = [NSFileManager defaultManager];
+                [fileManager copyItemAtPath:[url path] toPath:dumpFilePath error:&writeError];
+                if (nil != writeError) {
+                    if (shouldWaitForDownload) {
+                        self->SetCommandExitStatus(MTRErrorToCHIPErrorCode(readError));
+                    }
+                    return;
+                }
+            }
         }
 
-        VerifyOrReturn(nil == error, self->SetCommandExitStatus(MTRErrorToCHIPErrorCode(error)));
+        ChipLogProgress(chipTool, "Diagnostic logs transfer: %s", error ? "Error" : "Success");
+        auto err = RemoteDataModelLogger::LogBdxDownload(logContent, error);
 
-        // The url is nil when there are no logs on the target device.
-        if (nil == url) {
-            NSLog(@"No logs has been found onto node 0x" ChipLogFormatX64, ChipLogValueX64(mNodeId));
+        if (CHIP_NO_ERROR != err) {
+            if (shouldWaitForDownload) {
+                self->SetCommandExitStatus(err);
+            }
+            return;
+        }
+
+        if (shouldWaitForDownload) {
+            self->SetCommandExitStatus(MTRErrorToCHIPErrorCode(error));
         }
-        self->SetCommandExitStatus(CHIP_NO_ERROR);
     };
 
     [device downloadLogOfType:logType timeout:mTimeout queue:queue completion:completion];
+
+    if (!shouldWaitForDownload) {
+        SetCommandExitStatus(CHIP_NO_ERROR);
+    }
     return CHIP_NO_ERROR;
 }

examples/darwin-framework-tool/commands/common/RemoteDataModelLogger.h

@@ -32,5 +32,6 @@ CHIP_ERROR LogCommandAsJSON(NSNumber * endpointId, NSNumber * clusterId, NSNumbe
 CHIP_ERROR LogAttributeErrorAsJSON(NSNumber * endpointId, NSNumber * clusterId, NSNumber * attributeId, NSError * error);
 CHIP_ERROR LogCommandErrorAsJSON(NSNumber * endpointId, NSNumber * clusterId, NSNumber * commandId, NSError * error);
 CHIP_ERROR LogGetCommissionerNodeId(NSNumber * nodeId);
+CHIP_ERROR LogBdxDownload(NSString * content, NSError * error);
 void SetDelegate(RemoteDataModelLoggerDelegate * delegate);
 }; // namespace RemoteDataModelLogger

examples/darwin-framework-tool/commands/common/RemoteDataModelLogger.mm

@@ -35,6 +35,7 @@
 constexpr char kClusterErrorIdKey[] = "clusterError";
 constexpr char kValueKey[] = "value";
 constexpr char kNodeIdKey[] = "nodeId";
+constexpr char kLogContentIdKey[] = "logContent";
 
 constexpr char kBase64Header[] = "base64:";
 
@@ -204,5 +205,33 @@ CHIP_ERROR LogGetCommissionerNodeId(NSNumber * value)
     return gDelegate->LogJSON(valueStr.c_str());
 }
 
+CHIP_ERROR LogBdxDownload(NSString * content, NSError * error)
+{
+    VerifyOrReturnError(gDelegate != nullptr, CHIP_NO_ERROR);
+
+    Json::Value rootValue;
+    rootValue[kValueKey] = Json::Value();
+
+    Json::Value jsonValue;
+    VerifyOrDie(CHIP_NO_ERROR == AsJsonValue(content, jsonValue));
+    rootValue[kValueKey][kLogContentIdKey] = jsonValue;
+
+    if (error) {
+        auto err = MTRErrorToCHIPErrorCode(error);
+        auto status = chip::app::StatusIB(err);
+
+#if CHIP_CONFIG_IM_STATUS_CODE_VERBOSE_FORMAT
+        auto statusName = chip::Protocols::InteractionModel::StatusName(status.mStatus);
+        rootValue[kValueKey][kErrorIdKey] = statusName;
+#else
+        auto statusName = status.mStatus;
+        rootValue[kValueKey][kErrorIdKey] = chip::to_underlying(statusName);
+#endif // CHIP_CONFIG_IM_STATUS_CODE_VERBOSE_FORMAT
+    }
+
+    auto valueStr = JsonToString(rootValue);
+    return gDelegate->LogJSON(valueStr.c_str());
+}
+
 void SetDelegate(RemoteDataModelLoggerDelegate * delegate) { gDelegate = delegate; }
 }; // namespace RemoteDataModelLogger

scripts/py_matter_yamltests/matter_yamltests/pseudo_clusters/clusters/accessory_server_bridge.py

@@ -17,6 +17,7 @@
 import xmlrpc.client
 
 _DEFAULT_KEY = 'default'
+_DEFAULT_WAIT_FOR_MESSAGE_TIMEOUT_SECONDS = 10
 _IP = '127.0.0.1'
 _PORT = 9000
 
@@ -113,9 +114,11 @@ def factoryReset(request):
     def waitForMessage(request):
         register_key = _get_option(request, 'registerKey', _DEFAULT_KEY)
         message = _get_option(request, 'message')
+        timeout_in_seconds = _get_option(
+            request, 'timeoutInSeconds', _DEFAULT_WAIT_FOR_MESSAGE_TIMEOUT_SECONDS)
 
         with xmlrpc.client.ServerProxy(_make_url(), allow_none=True) as proxy:
-            proxy.waitForMessage(register_key, [message])
+            proxy.waitForMessage(register_key, [message], timeout_in_seconds)
 
     def createOtaImage(request):
         otaImageFilePath = _get_option(request, 'otaImageFilePath')

scripts/py_matter_yamltests/matter_yamltests/pseudo_clusters/clusters/delay_commands.py

@@ -40,6 +40,7 @@
     <command source="client" code="3" name="WaitForMessage">
       <arg name="registerKey" type="char_string"/>
       <arg name="message" type="char_string"/>
+      <arg name="timeoutInSeconds" type="int16u" optional="true"/>
     </command>
 </cluster>
 </configurator>

scripts/tests/chiptest/__init__.py

@@ -160,6 +160,13 @@ def _GetInDevelopmentTests() -> Set[str]:
     }
 
 
+def _GetChipToolUnsupportedTests() -> Set[str]:
+    """Tests that fail in chip-tool for some reason"""
+    return {
+        "TestDiagnosticLogsDownloadCommand",  # chip-tool does not implement a bdx download command.
+    }
+
+
 def _GetDarwinFrameworkToolUnsupportedTests() -> Set[str]:
     """Tests that fail in darwin-framework-tool for some reason"""
     return {
@@ -258,6 +265,7 @@ def _GetChipReplUnsupportedTests() -> Set[str]:
         "Test_TC_RVCCLEANM_3_3.yaml",            # chip-repl does not support EqualityCommands pseudo-cluster
         "Test_TC_BINFO_2_1.yaml",            # chip-repl does not support EqualityCommands pseudo-cluster
         "TestDiagnosticLogs.yaml",          # chip-repl does not implement a BDXTransferServerDelegate
+        "TestDiagnosticLogsDownloadCommand.yaml",  # chip-repl does not implement the bdx download command
     }
 
 
@@ -340,7 +348,7 @@ def tests_with_command(chip_tool: str, is_manual: bool):
         )
 
 
-def _AllFoundYamlTests(treat_repl_unsupported_as_in_development: bool, treat_dft_unsupported_as_in_development: bool, use_short_run_name: bool):
+def _AllFoundYamlTests(treat_repl_unsupported_as_in_development: bool, treat_dft_unsupported_as_in_development: bool, treat_chip_tool_unsupported_as_in_development: bool, use_short_run_name: bool):
     """
     use_short_run_name should be true if we want the run_name to be "Test_ABC" instead of "some/path/Test_ABC.yaml"
     """
@@ -350,7 +358,8 @@ def _AllFoundYamlTests(treat_repl_unsupported_as_in_development: bool, treat_dft
     extra_slow_tests = _GetExtraSlowTests()
     in_development_tests = _GetInDevelopmentTests()
     chip_repl_unsupported_tests = _GetChipReplUnsupportedTests()
-    treat_dft_unsupported_as_in_development_tests = _GetDarwinFrameworkToolUnsupportedTests()
+    dft_unsupported_as_in_development_tests = _GetDarwinFrameworkToolUnsupportedTests()
+    chip_tool_unsupported_as_in_development_tests = _GetChipToolUnsupportedTests()
     purposeful_failure_tests = _GetPurposefulFailureTests()
 
     for path in _AllYamlTests():
@@ -384,7 +393,10 @@ def _AllFoundYamlTests(treat_repl_unsupported_as_in_development: bool, treat_dft
         else:
             run_name = str(path)
 
-        if treat_dft_unsupported_as_in_development and run_name in treat_dft_unsupported_as_in_development_tests:
+        if treat_dft_unsupported_as_in_development and run_name in dft_unsupported_as_in_development_tests:
+            tags.add(TestTag.IN_DEVELOPMENT)
+
+        if treat_chip_tool_unsupported_as_in_development and run_name in chip_tool_unsupported_as_in_development_tests:
             tags.add(TestTag.IN_DEVELOPMENT)
 
         yield TestDefinition(
@@ -396,17 +408,17 @@ def _AllFoundYamlTests(treat_repl_unsupported_as_in_development: bool, treat_dft
 
 
 def AllReplYamlTests():
-    for test in _AllFoundYamlTests(treat_repl_unsupported_as_in_development=True, treat_dft_unsupported_as_in_development=False, use_short_run_name=False):
+    for test in _AllFoundYamlTests(treat_repl_unsupported_as_in_development=True, treat_dft_unsupported_as_in_development=False, treat_chip_tool_unsupported_as_in_development=False, use_short_run_name=False):
         yield test
 
 
 def AllChipToolYamlTests():
-    for test in _AllFoundYamlTests(treat_repl_unsupported_as_in_development=False, treat_dft_unsupported_as_in_development=False, use_short_run_name=True):
+    for test in _AllFoundYamlTests(treat_repl_unsupported_as_in_development=False, treat_dft_unsupported_as_in_development=False, treat_chip_tool_unsupported_as_in_development=True, use_short_run_name=True):
         yield test
 
 
 def AllDarwinFrameworkToolYamlTests():
-    for test in _AllFoundYamlTests(treat_repl_unsupported_as_in_development=False, treat_dft_unsupported_as_in_development=True, use_short_run_name=True):
+    for test in _AllFoundYamlTests(treat_repl_unsupported_as_in_development=False, treat_dft_unsupported_as_in_development=True, treat_chip_tool_unsupported_as_in_development=False, use_short_run_name=True):
         yield test
 
 

scripts/tests/chiptest/accessories.py

@@ -98,12 +98,12 @@ def factoryReset(self, name):
             return accessory.factoryReset()
         return False
 
-    def waitForMessage(self, name, message):
+    def waitForMessage(self, name, message, timeoutInSeconds=10):
         accessory = self.__accessories[name]
         if accessory:
             # The message param comes directly from the sys.argv[2:] of WaitForMessage.py and should contain a list of strings that
             # comprise the entire message to wait for
-            return accessory.waitForMessage(' '.join(message))
+            return accessory.waitForMessage(' '.join(message), timeoutInSeconds)
         return False
 
     def createOtaImage(self, otaImageFilePath, rawImageFilePath, rawImageContent, vid='0xDEAD', pid='0xBEEF'):

scripts/tests/chiptest/test_definition.py

@@ -83,8 +83,8 @@ def factoryReset(self):
     def waitForAnyAdvertisement(self):
         self.__waitFor("mDNS service published:", self.process, self.outpipe)
 
-    def waitForMessage(self, message):
-        self.__waitFor(message, self.process, self.outpipe)
+    def waitForMessage(self, message, timeoutInSeconds=10):
+        self.__waitFor(message, self.process, self.outpipe, timeoutInSeconds)
         return True
 
     def kill(self):
@@ -124,7 +124,7 @@ def __startServer(self, runner, command):
                     self.kvsPathSet.add(value)
         return runner.RunSubprocess(app_cmd, name='APP ', wait=False)
 
-    def __waitFor(self, waitForString, server_process, outpipe):
+    def __waitFor(self, waitForString, server_process, outpipe, timeoutInSeconds=10):
         logging.debug('Waiting for %s' % waitForString)
 
         start_time = time.monotonic()
@@ -139,7 +139,7 @@ def __waitFor(self, waitForString, server_process, outpipe):
                             (waitForString, server_process.returncode))
                 logging.error(died_str)
                 raise Exception(died_str)
-            if time.monotonic() - start_time > 10:
+            if time.monotonic() - start_time > timeoutInSeconds:
                 raise Exception('Timeout while waiting for %s' % waitForString)
             time.sleep(0.1)
             ready, self.lastLogIndex = outpipe.CapturedLogContains(
@@ -336,6 +336,13 @@ def Run(self, runner, apps_register, paths: ApplicationPaths, pics_file: str,
                     # so it will be commissionable again.
                     app.factoryReset()
 
+                    # It may sometimes be useful to run the same app multiple times depending
+                    # on the implementation. So this code creates a duplicate entry but with a different
+                    # key.
+                    app = App(runner, path)
+                    apps_register.add(f'{key}#2', app)
+                    app.factoryReset()
+
             if dry_run:
                 tool_storage_dir = None
                 tool_storage_args = []