Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Diagnostic Logs] Followup for #31638 #31833

Merged
merged 4 commits into from
Feb 13, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -148,6 +148,17 @@
}
},

'Bdx': {
'commands': {
'Download': {
'arguments': {
'LogType': 'log-type',
},
'has_endpoint': False,
}
}
},

'DelayCommands': {
'alias': 'delay',
'commands': {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
};
Original file line number Diff line number Diff line change
Expand Up @@ -21,6 +21,7 @@
#import "MTRError_Utils.h"

#include "DownloadLogCommand.h"
#include "RemoteDataModelLogger.h"

CHIP_ERROR DownloadLogCommand::RunCommand()
{
Expand All @@ -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;
}
Original file line number Diff line number Diff line change
Expand Up @@ -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
Original file line number Diff line number Diff line change
Expand Up @@ -35,6 +35,7 @@
constexpr char kClusterErrorIdKey[] = "clusterError";
constexpr char kValueKey[] = "value";
constexpr char kNodeIdKey[] = "nodeId";
constexpr char kLogContentIdKey[] = "logContent";

constexpr char kBase64Header[] = "base64:";

Expand Down Expand Up @@ -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
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,7 @@
import xmlrpc.client

_DEFAULT_KEY = 'default'
_DEFAULT_WAIT_FOR_MESSAGE_TIMEOUT_SECONDS = 10
_IP = '127.0.0.1'
_PORT = 9000

Expand Down Expand Up @@ -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')
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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>
Expand Down
24 changes: 18 additions & 6 deletions scripts/tests/chiptest/__init__.py
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down Expand Up @@ -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
}


Expand Down Expand Up @@ -338,7 +346,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"
"""
Expand All @@ -348,7 +356,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():
Expand Down Expand Up @@ -382,7 +391,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(
Expand All @@ -394,17 +406,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


Expand Down
4 changes: 2 additions & 2 deletions scripts/tests/chiptest/accessories.py
Original file line number Diff line number Diff line change
Expand Up @@ -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'):
Expand Down
15 changes: 11 additions & 4 deletions scripts/tests/chiptest/test_definition.py
Original file line number Diff line number Diff line change
Expand Up @@ -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):
Expand Down Expand Up @@ -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()
Expand All @@ -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(
Expand Down Expand Up @@ -332,6 +332,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 = []
Expand Down
Loading
Loading