1 # Copyright 2018 The Chromium OS Authors. All rights reserved. 2 # Use of this source code is governed by a BSD-style license that can be 3 # found in the LICENSE file. 4 5 import json 6 import logging 7 import os 8 9 import dateutil.parser 10 11 from autotest_lib.client.common_lib import base_job 12 from autotest_lib.client.common_lib import error 13 from autotest_lib.client.common_lib.cros import dev_server 14 from autotest_lib.server import test 15 from autotest_lib.server import utils 16 17 18 # A datetime.DateTime representing the Unix epoch in UTC. 19 _UNIX_EPOCH = dateutil.parser.parse('1970-01-01T00:00:00Z') 20 21 22 class tast(test.test): 23 """Autotest server test that runs a Tast test suite. 24 25 Tast is an integration-testing framework analagous to the test-running 26 portion of Autotest. See 27 https://chromium.googlesource.com/chromiumos/platform/tast/ for more 28 information. 29 30 This class runs the "tast" command locally to execute a Tast test suite on a 31 remote DUT. 32 """ 33 version = 1 34 35 # Maximum time to wait for various tast commands to complete, in seconds. 36 # Note that _LIST_TIMEOUT_SEC includes time to download private test bundles 37 # if run_private_tests=True. 38 _VERSION_TIMEOUT_SEC = 10 39 _LIST_TIMEOUT_SEC = 60 40 41 # Additional time to add to the run timeout (e.g. for collecting crashes and 42 # logs). 43 _RUN_OVERHEAD_SEC = 20 44 # Additional time given to the run command to exit before it's killed. 45 _RUN_EXIT_SEC = 5 46 47 # Number of times to retry SSH connection attempts to the DUT. 48 _SSH_CONNECT_RETRIES = 2 49 50 # File written by the tast command containing test results, as 51 # newline-terminated JSON TestResult objects. 52 _STREAMED_RESULTS_FILENAME = 'streamed_results.jsonl' 53 54 # Text file written by the tast command if a global error caused the test 55 # run to fail (e.g. SSH connection to DUT was lost). 56 _RUN_ERROR_FILENAME = 'run_error.txt' 57 58 # Maximum number of failing and missing tests to include in error messages. 59 _MAX_TEST_NAMES_IN_ERROR = 3 60 61 # Default paths where Tast files are installed by Portage packages. 62 _TAST_PATH = '/usr/bin/tast' 63 _REMOTE_BUNDLE_DIR = '/usr/libexec/tast/bundles/remote' 64 _REMOTE_DATA_DIR = '/usr/share/tast/data' 65 _REMOTE_TEST_RUNNER_PATH = '/usr/bin/remote_test_runner' 66 67 # Alternate locations for Tast files when using Server-Side Packaging. 68 # These files are installed from autotest_server_package.tar.bz2. 69 _SSP_ROOT = '/usr/local/tast' 70 _SSP_TAST_PATH = os.path.join(_SSP_ROOT, 'tast') 71 _SSP_REMOTE_BUNDLE_DIR = os.path.join(_SSP_ROOT, 'bundles/remote') 72 _SSP_REMOTE_DATA_DIR = os.path.join(_SSP_ROOT, 'data') 73 _SSP_REMOTE_TEST_RUNNER_PATH = os.path.join(_SSP_ROOT, 'remote_test_runner') 74 75 # Prefix added to Tast test names when writing their results to TKO 76 # status.log files. 77 _TEST_NAME_PREFIX = 'tast.' 78 79 # Prefixes of keyval keys recorded for missing tests. 80 _MISSING_TEST_KEYVAL_PREFIX = 'tast_missing_test.' 81 82 # Job start/end TKO event status codes from base_client_job._rungroup in 83 # client/bin/job.py. 84 _JOB_STATUS_START = 'START' 85 _JOB_STATUS_END_GOOD = 'END GOOD' 86 _JOB_STATUS_END_FAIL = 'END FAIL' 87 _JOB_STATUS_END_ABORT = 'END ABORT' 88 89 # In-job TKO event status codes from base_client_job._run_test_base in 90 # client/bin/job.py and client/common_lib/error.py. 91 _JOB_STATUS_GOOD = 'GOOD' 92 _JOB_STATUS_FAIL = 'FAIL' 93 94 # Status reason used when an individual Tast test doesn't finish running. 95 _TEST_DID_NOT_FINISH_MSG = 'Test did not finish' 96 97 def initialize(self, host, test_exprs, ignore_test_failures=False, 98 max_run_sec=3600, install_root='/', run_private_tests=True): 99 """ 100 @param host: remote.RemoteHost instance representing DUT. 101 @param test_exprs: Array of strings describing tests to run. 102 @param ignore_test_failures: If False, this test will fail if individual 103 Tast tests report failure. If True, this test will only fail in 104 response to the tast command failing to run successfully. This 105 should generally be False when the test is running inline and True 106 when it's running asynchronously. 107 @param max_run_sec: Integer maximum running time for the "tast run" 108 command in seconds. 109 @param install_root: Root directory under which Tast binaries are 110 installed. Alternate values may be passed by unit tests. 111 @param run_private_tests: Download and run private tests. 112 113 @raises error.TestFail if the Tast installation couldn't be found. 114 """ 115 self._host = host 116 self._test_exprs = test_exprs 117 self._ignore_test_failures = ignore_test_failures 118 self._max_run_sec = max_run_sec 119 self._install_root = install_root 120 self._run_private_tests = run_private_tests 121 self._fake_now = None 122 123 # List of JSON objects describing tests that will be run. See Test in 124 # src/platform/tast/src/chromiumos/tast/testing/test.go for details. 125 self._tests_to_run = [] 126 127 # List of JSON objects corresponding to tests from 128 # _STREAMED_RESULTS_FILENAME. See TestResult in 129 # src/platform/tast/src/chromiumos/cmd/tast/run/results.go for details. 130 self._test_results = [] 131 132 # Error message read from _RUN_ERROR_FILENAME, if any. 133 self._run_error = None 134 135 # The data dir can be missing if no remote tests registered data files, 136 # but all other files must exist. 137 self._tast_path = self._get_path((self._TAST_PATH, self._SSP_TAST_PATH)) 138 self._remote_bundle_dir = self._get_path((self._REMOTE_BUNDLE_DIR, 139 self._SSP_REMOTE_BUNDLE_DIR)) 140 self._remote_data_dir = self._get_path((self._REMOTE_DATA_DIR, 141 self._SSP_REMOTE_DATA_DIR), 142 allow_missing=True) 143 self._remote_test_runner_path = self._get_path( 144 (self._REMOTE_TEST_RUNNER_PATH, 145 self._SSP_REMOTE_TEST_RUNNER_PATH)) 146 147 # Register a hook to write the results of individual Tast tests as 148 # top-level entries in the TKO status.log file. 149 self.job.add_post_run_hook(self._log_all_tests) 150 151 def run_once(self): 152 """Runs a single iteration of the test.""" 153 self._log_version() 154 self._find_devservers() 155 self._get_tests_to_run() 156 157 run_failed = False 158 try: 159 self._run_tests() 160 except: 161 run_failed = True 162 raise 163 finally: 164 self._read_run_error() 165 # Parse partial results even if the tast command didn't finish. 166 self._parse_results(run_failed) 167 168 def set_fake_now_for_testing(self, now): 169 """Sets a fake timestamp to use in place of time.time() for unit tests. 170 171 @param now Numeric timestamp as would be returned by time.time(). 172 """ 173 self._fake_now = now 174 175 def _get_path(self, paths, allow_missing=False): 176 """Returns the path to an installed Tast-related file or directory. 177 178 @param paths: Tuple or list of absolute paths in root filesystem, e.g. 179 ("/usr/bin/tast", "/usr/local/tast/tast"). 180 @param allow_missing: True if it's okay for the path to be missing. 181 182 @returns Absolute path within install root, e.g. "/usr/bin/tast", or an 183 empty string if the path wasn't found and allow_missing is True. 184 185 @raises error.TestFail if the path couldn't be found and allow_missing 186 is False. 187 """ 188 for path in paths: 189 abs_path = os.path.join(self._install_root, 190 os.path.relpath(path, '/')) 191 if os.path.exists(abs_path): 192 return abs_path 193 194 if allow_missing: 195 return '' 196 raise error.TestFail('None of %s exist' % list(paths)) 197 198 def _find_devservers(self): 199 """Finds available devservers. 200 201 The result is saved as self._devserver_args. 202 """ 203 devservers, _ = dev_server.ImageServer.get_available_devservers( 204 self._host.hostname) 205 logging.info('Using devservers: %s', ', '.join(devservers)) 206 self._devserver_args = ['-devservers=%s' % ','.join(devservers)] 207 208 def _log_version(self): 209 """Runs the tast command locally to log its version.""" 210 try: 211 utils.run([self._tast_path, '-version'], 212 timeout=self._VERSION_TIMEOUT_SEC, 213 stdout_tee=utils.TEE_TO_LOGS, 214 stderr_tee=utils.TEE_TO_LOGS, 215 stderr_is_expected=True, 216 stdout_level=logging.INFO, 217 stderr_level=logging.ERROR) 218 except error.CmdError as e: 219 logging.error('Failed to log tast version: %s', str(e)) 220 221 def _run_tast(self, subcommand, extra_subcommand_args, timeout_sec, 222 log_stdout=False): 223 """Runs the tast command locally to e.g. list available tests or perform 224 testing against the DUT. 225 226 @param subcommand: Subcommand to pass to the tast executable, e.g. 'run' 227 or 'list'. 228 @param extra_subcommand_args: List of additional subcommand arguments. 229 @param timeout_sec: Integer timeout for the command in seconds. 230 @param log_stdout: If true, write stdout to log. 231 232 @returns client.common_lib.utils.CmdResult object describing the result. 233 234 @raises error.TestFail if the tast command fails or times out. 235 """ 236 cmd = [ 237 self._tast_path, 238 '-verbose=true', 239 '-logtime=false', 240 subcommand, 241 '-build=false', 242 '-remotebundledir=' + self._remote_bundle_dir, 243 '-remotedatadir=' + self._remote_data_dir, 244 '-remoterunner=' + self._remote_test_runner_path, 245 '-sshretries=%d' % self._SSH_CONNECT_RETRIES, 246 ] 247 cmd.extend(extra_subcommand_args) 248 cmd.append('%s:%d' % (self._host.hostname, self._host.port)) 249 cmd.extend(self._test_exprs) 250 251 logging.info('Running ' + 252 ' '.join([utils.sh_quote_word(a) for a in cmd])) 253 try: 254 return utils.run(cmd, 255 ignore_status=False, 256 timeout=timeout_sec, 257 stdout_tee=(utils.TEE_TO_LOGS if log_stdout 258 else None), 259 stderr_tee=utils.TEE_TO_LOGS, 260 stderr_is_expected=True, 261 stdout_level=logging.INFO, 262 stderr_level=logging.ERROR) 263 except error.CmdError as e: 264 # The tast command's output generally ends with a line describing 265 # the error that was encountered; include it in the first line of 266 # the TestFail exception. Fall back to stderr if stdout is empty (as 267 # is the case with the "list" subcommand, which uses stdout to print 268 # test data). 269 get_last_line = lambda s: s.strip().split('\n')[-1].strip() 270 last_line = (get_last_line(e.result_obj.stdout) or 271 get_last_line(e.result_obj.stderr)) 272 msg = (' (last line: %s)' % last_line) if last_line else '' 273 raise error.TestFail('Failed to run tast%s: %s' % (msg, str(e))) 274 except error.CmdTimeoutError as e: 275 raise error.TestFail('Got timeout while running tast: %s' % str(e)) 276 277 def _get_tests_to_run(self): 278 """Runs the tast command to update the list of tests that will be run. 279 280 @raises error.TestFail if the tast command fails or times out. 281 """ 282 logging.info('Getting list of tests that will be run') 283 args = ['-json=true'] + self._devserver_args 284 if self._run_private_tests: 285 args.append('-downloadprivatebundles=true') 286 result = self._run_tast('list', args, self._LIST_TIMEOUT_SEC) 287 try: 288 self._tests_to_run = json.loads(result.stdout.strip()) 289 except ValueError as e: 290 raise error.TestFail('Failed to parse tests: %s' % str(e)) 291 if len(self._tests_to_run) == 0: 292 expr = ' '.join([utils.sh_quote_word(a) for a in self._test_exprs]) 293 raise error.TestFail('No tests matched by %s' % expr) 294 295 logging.info('Expect to run %d test(s)', len(self._tests_to_run)) 296 297 def _run_tests(self): 298 """Runs the tast command to perform testing. 299 300 @raises error.TestFail if the tast command fails or times out (but not 301 if individual tests fail). 302 """ 303 timeout_sec = self._get_run_tests_timeout_sec() 304 logging.info('Running tests with timeout of %d sec', timeout_sec) 305 args = [ 306 '-resultsdir=' + self.resultsdir, 307 '-waituntilready=true', 308 '-timeout=' + str(timeout_sec), 309 ] + self._devserver_args 310 if self._run_private_tests: 311 args.append('-downloadprivatebundles=true') 312 self._run_tast('run', args, timeout_sec + tast._RUN_EXIT_SEC, 313 log_stdout=True) 314 315 def _get_run_tests_timeout_sec(self): 316 """Computes the timeout for the 'tast run' command. 317 318 @returns Integer timeout in seconds. 319 """ 320 # Go time.Duration values are serialized to nanoseconds. 321 total_ns = sum([int(t['timeout']) for t in self._tests_to_run]) 322 return min(total_ns / 1000000000 + tast._RUN_OVERHEAD_SEC, 323 self._max_run_sec) 324 325 def _read_run_error(self): 326 """Reads a global run error message written by the tast command.""" 327 # The file is only written if a run error occurred. 328 path = os.path.join(self.resultsdir, self._RUN_ERROR_FILENAME) 329 if os.path.exists(path): 330 with open(path, 'r') as f: 331 self._run_error = f.read().strip() 332 333 def _parse_results(self, ignore_missing_file): 334 """Parses results written by the tast command. 335 336 @param ignore_missing_file: If True, return without raising an exception 337 if the Tast results file is missing. This is used to avoid raising a 338 new error if there was already an earlier error while running the 339 tast process. 340 341 @raises error.TestFail if results file is missing and 342 ignore_missing_file is False, or one or more tests failed and 343 _ignore_test_failures is false. 344 """ 345 # The file may not exist if "tast run" failed to run. Tests that were 346 # seen from the earlier "tast list" command will be reported as having 347 # missing results. 348 path = os.path.join(self.resultsdir, self._STREAMED_RESULTS_FILENAME) 349 if not os.path.exists(path): 350 if ignore_missing_file: 351 return 352 raise error.TestFail('Results file %s not found' % path) 353 354 failed = [] 355 seen_test_names = set() 356 with open(path, 'r') as f: 357 for line in f: 358 line = line.strip() 359 if not line: 360 continue 361 try: 362 test = json.loads(line) 363 except ValueError as e: 364 raise error.TestFail('Failed to parse %s: %s' % (path, e)) 365 self._test_results.append(test) 366 367 name = test['name'] 368 seen_test_names.add(name) 369 370 if test.get('errors'): 371 for err in test['errors']: 372 logging.warning('%s: %s', name, err['reason']) 373 failed.append(name) 374 else: 375 # The test will have a zero (i.e. 0001-01-01 00:00:00 UTC) 376 # end time (preceding the Unix epoch) if it didn't report 377 # completion. 378 if _rfc3339_time_to_timestamp(test['end']) <= 0: 379 failed.append(name) 380 381 missing = [t['name'] for t in self._tests_to_run 382 if t['name'] not in seen_test_names] 383 384 if missing: 385 self._record_missing_tests(missing) 386 387 failure_msg = self._get_failure_message(failed, missing) 388 if failure_msg: 389 raise error.TestFail(failure_msg) 390 391 def _get_failure_message(self, failed, missing): 392 """Returns an error message describing failed and/or missing tests. 393 394 @param failed: List of string names of Tast tests that failed. 395 @param missing: List of string names of Tast tests with missing results. 396 397 @returns String to be used as error.TestFail message. 398 """ 399 def list_tests(names): 400 """Returns a string listing tests. 401 402 @param names: List of string test names. 403 404 @returns String listing tests. 405 """ 406 s = ' '.join(sorted(names)[:self._MAX_TEST_NAMES_IN_ERROR]) 407 if len(names) > self._MAX_TEST_NAMES_IN_ERROR: 408 s += ' ...' 409 return s 410 411 msg = '' 412 if failed and not self._ignore_test_failures: 413 msg = '%d failed: %s' % (len(failed), list_tests(failed)) 414 if missing: 415 if msg: 416 msg += '; ' 417 msg += '%d missing: %s' % (len(missing), list_tests(missing)) 418 return msg 419 420 def _log_all_tests(self): 421 """Writes entries to the TKO status.log file describing the results of 422 all tests. 423 """ 424 seen_test_names = set() 425 for test in self._test_results: 426 self._log_test(test) 427 seen_test_names.add(test['name']) 428 429 def _log_test(self, test): 430 """Writes events to the TKO status.log file describing the results from 431 a Tast test. 432 433 @param test: A JSON object corresponding to a single test from a Tast 434 results.json file. See TestResult in 435 src/platform/tast/src/chromiumos/cmd/tast/run/results.go for 436 details. 437 """ 438 name = test['name'] 439 start_time = _rfc3339_time_to_timestamp(test['start']) 440 end_time = _rfc3339_time_to_timestamp(test['end']) 441 442 test_reported_errors = bool(test.get('errors')) 443 test_skipped = bool(test.get('skipReason')) 444 # The test will have a zero (i.e. 0001-01-01 00:00:00 UTC) end time 445 # (preceding the Unix epoch) if it didn't report completion. 446 test_finished = end_time > 0 447 448 # Avoid reporting tests that were skipped. 449 if test_skipped and not test_reported_errors: 450 return 451 452 self._log_test_event(self._JOB_STATUS_START, name, start_time) 453 454 if test_finished and not test_reported_errors: 455 self._log_test_event(self._JOB_STATUS_GOOD, name, end_time) 456 end_status = self._JOB_STATUS_END_GOOD 457 else: 458 # The previous START event automatically increases the log 459 # indentation level until the following END event. 460 if test_reported_errors: 461 for err in test['errors']: 462 error_time = _rfc3339_time_to_timestamp(err['time']) 463 self._log_test_event(self._JOB_STATUS_FAIL, name, 464 error_time, err['reason']) 465 if not test_finished: 466 # If a run-level error was encountered (e.g. the SSH connection 467 # to the DUT was lost), report it here to make it easier to see 468 # the reason why the test didn't finish. 469 if self._run_error: 470 self._log_test_event(self._JOB_STATUS_FAIL, name, 471 start_time, self._run_error) 472 self._log_test_event(self._JOB_STATUS_FAIL, name, start_time, 473 self._TEST_DID_NOT_FINISH_MSG) 474 end_time = start_time 475 476 end_status = self._JOB_STATUS_END_FAIL 477 478 self._log_test_event(end_status, name, end_time) 479 480 def _log_test_event(self, status_code, test_name, timestamp, message=''): 481 """Logs a single event to the TKO status.log file. 482 483 @param status_code: Event status code, e.g. 'END GOOD'. See 484 client/common_lib/log.py for accepted values. 485 @param test_name: Tast test name, e.g. 'ui.ChromeLogin'. 486 @param timestamp: Event timestamp (as seconds since Unix epoch). 487 @param message: Optional human-readable message. 488 """ 489 full_name = self._TEST_NAME_PREFIX + test_name 490 # The TKO parser code chokes on floating-point timestamps. 491 entry = base_job.status_log_entry(status_code, None, full_name, message, 492 None, timestamp=int(timestamp)) 493 self.job.record_entry(entry, False) 494 495 def _record_missing_tests(self, missing): 496 """Records tests with missing results in job keyval file. 497 498 @param missing: List of string names of Tast tests with missing results. 499 """ 500 keyvals = {} 501 for i, name in enumerate(sorted(missing)): 502 keyvals['%s%d' % (self._MISSING_TEST_KEYVAL_PREFIX, i)] = name 503 utils.write_keyval(self.job.resultdir, keyvals) 504 505 506 class _LessBrokenParserInfo(dateutil.parser.parserinfo): 507 """dateutil.parser.parserinfo that interprets years before 100 correctly. 508 509 Our version of dateutil.parser.parse misinteprets an unambiguous string like 510 '0001-01-01T00:00:00Z' as having a two-digit year, which it then converts to 511 2001. This appears to have been fixed by 512 https://github.com/dateutil/dateutil/commit/fc696254. This parserinfo 513 implementation always honors the provided year to prevent this from 514 happening. 515 """ 516 def convertyear(self, year, century_specified=False): 517 """Overrides convertyear in dateutil.parser.parserinfo.""" 518 return int(year) 519 520 521 def _rfc3339_time_to_timestamp(time_str): 522 """Converts an RFC3339 time into a Unix timestamp. 523 524 @param time_str: RFC3339-compatible time, e.g. 525 '2018-02-25T07:45:35.916929332-07:00'. 526 527 @returns Float number of seconds since the Unix epoch. Negative if the time 528 precedes the epoch. 529 """ 530 dt = dateutil.parser.parse(time_str, parserinfo=_LessBrokenParserInfo()) 531 return (dt - _UNIX_EPOCH).total_seconds() 532
