1# Copyright 2018, The Android Open Source Project 2# 3# Licensed under the Apache License, Version 2.0 (the "License"); 4# you may not use this file except in compliance with the License. 5# You may obtain a copy of the License at 6# 7# http://www.apache.org/licenses/LICENSE-2.0 8# 9# Unless required by applicable law or agreed to in writing, software 10# distributed under the License is distributed on an "AS IS" BASIS, 11# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 12# See the License for the specific language governing permissions and 13# limitations under the License. 14 15# pylint: disable=import-outside-toplevel 16# pylint: disable=line-too-long 17 18""" 19Result Reporter 20 21The result reporter formats and prints test results. 22 23---- 24Example Output for command to run following tests: 25CtsAnimationTestCases:EvaluatorTest, HelloWorldTests, and WmTests 26 27Running Tests ... 28 29CtsAnimationTestCases 30--------------------- 31 32android.animation.cts.EvaluatorTest.UnitTests (7 Tests) 33[1/7] android.animation.cts.EvaluatorTest#testRectEvaluator: PASSED (153ms) 34[2/7] android.animation.cts.EvaluatorTest#testIntArrayEvaluator: PASSED (0ms) 35[3/7] android.animation.cts.EvaluatorTest#testIntEvaluator: PASSED (0ms) 36[4/7] android.animation.cts.EvaluatorTest#testFloatArrayEvaluator: PASSED (1ms) 37[5/7] android.animation.cts.EvaluatorTest#testPointFEvaluator: PASSED (1ms) 38[6/7] android.animation.cts.EvaluatorTest#testArgbEvaluator: PASSED (0ms) 39[7/7] android.animation.cts.EvaluatorTest#testFloatEvaluator: PASSED (1ms) 40 41HelloWorldTests 42--------------- 43 44android.test.example.helloworld.UnitTests(2 Tests) 45[1/2] android.test.example.helloworld.HelloWorldTest#testHalloWelt: PASSED (0ms) 46[2/2] android.test.example.helloworld.HelloWorldTest#testHelloWorld: PASSED (1ms) 47 48WmTests 49------- 50 51com.android.tradefed.targetprep.UnitTests (1 Test) 52RUNNER ERROR: com.android.tradefed.targetprep.TargetSetupError: 53Failed to install WmTests.apk on 127.0.0.1:54373. Reason: 54 error message ... 55 56 57Summary 58------- 59CtsAnimationTestCases: Passed: 7, Failed: 0 60HelloWorldTests: Passed: 2, Failed: 0 61WmTests: Passed: 0, Failed: 0 (Completed With ERRORS) 62 631 test failed 64""" 65 66from __future__ import print_function 67 68from collections import OrderedDict 69 70import constants 71import atest_utils as au 72 73from test_runners import test_runner_base 74 75UNSUPPORTED_FLAG = 'UNSUPPORTED_RUNNER' 76FAILURE_FLAG = 'RUNNER_FAILURE' 77BENCHMARK_ESSENTIAL_KEYS = {'repetition_index', 'cpu_time', 'name', 'repetitions', 78 'run_type', 'threads', 'time_unit', 'iterations', 79 'run_name', 'real_time'} 80# TODO(b/146875480): handle the optional benchmark events 81BENCHMARK_OPTIONAL_KEYS = {'bytes_per_second', 'label'} 82BENCHMARK_EVENT_KEYS = BENCHMARK_ESSENTIAL_KEYS.union(BENCHMARK_OPTIONAL_KEYS) 83INT_KEYS = {'cpu_time', 'real_time'} 84ITER_SUMMARY = {} 85 86class PerfInfo(): 87 """Class for storing performance test of a test run.""" 88 89 def __init__(self): 90 """Initialize a new instance of PerfInfo class.""" 91 # perf_info: A list of benchmark_info(dict). 92 self.perf_info = [] 93 94 def update_perf_info(self, test): 95 """Update perf_info with the given result of a single test. 96 97 Args: 98 test: A TestResult namedtuple. 99 """ 100 all_additional_keys = set(test.additional_info.keys()) 101 # Ensure every key is in all_additional_keys. 102 if not BENCHMARK_ESSENTIAL_KEYS.issubset(all_additional_keys): 103 return 104 benchmark_info = {} 105 benchmark_info['test_name'] = test.test_name 106 for key, data in test.additional_info.items(): 107 if key in INT_KEYS: 108 data_to_int = data.split('.')[0] 109 benchmark_info[key] = data_to_int 110 elif key in BENCHMARK_EVENT_KEYS: 111 benchmark_info[key] = data 112 if benchmark_info: 113 self.perf_info.append(benchmark_info) 114 115 def print_perf_info(self): 116 """Print summary of a perf_info.""" 117 if not self.perf_info: 118 return 119 classify_perf_info, max_len = self._classify_perf_info() 120 separator = '-' * au.get_terminal_size()[0] 121 print(separator) 122 print("{:{name}} {:^{real_time}} {:^{cpu_time}} " 123 "{:>{iterations}}".format( 124 'Benchmark', 'Time', 'CPU', 'Iteration', 125 name=max_len['name']+3, 126 real_time=max_len['real_time']+max_len['time_unit']+1, 127 cpu_time=max_len['cpu_time']+max_len['time_unit']+1, 128 iterations=max_len['iterations'])) 129 print(separator) 130 for module_name, module_perf_info in classify_perf_info.items(): 131 print("{}:".format(module_name)) 132 for benchmark_info in module_perf_info: 133 # BpfBenchMark/MapWriteNewEntry/1 1530 ns 1522 ns 460517 134 print(" #{:{name}} {:>{real_time}} {:{time_unit}} " 135 "{:>{cpu_time}} {:{time_unit}} " 136 "{:>{iterations}}".format(benchmark_info['name'], 137 benchmark_info['real_time'], 138 benchmark_info['time_unit'], 139 benchmark_info['cpu_time'], 140 benchmark_info['time_unit'], 141 benchmark_info['iterations'], 142 name=max_len['name'], 143 real_time=max_len['real_time'], 144 time_unit=max_len['time_unit'], 145 cpu_time=max_len['cpu_time'], 146 iterations=max_len['iterations'])) 147 148 def _classify_perf_info(self): 149 """Classify the perf_info by test module name. 150 151 Returns: 152 A tuple of (classified_perf_info, max_len), where 153 classified_perf_info: A dict of perf_info and each perf_info are 154 belong to different modules. 155 e.g. 156 { module_name_01: [perf_info of module_1], 157 module_name_02: [perf_info of module_2], ...} 158 max_len: A dict which stores the max length of each event. 159 It contains the max string length of 'name', real_time', 160 'time_unit', 'cpu_time', 'iterations'. 161 e.g. 162 {name: 56, real_time: 9, time_unit: 2, cpu_time: 8, 163 iterations: 12} 164 """ 165 module_categories = set() 166 max_len = {} 167 all_name = [] 168 all_real_time = [] 169 all_time_unit = [] 170 all_cpu_time = [] 171 all_iterations = ['Iteration'] 172 for benchmark_info in self.perf_info: 173 module_categories.add(benchmark_info['test_name'].split('#')[0]) 174 all_name.append(benchmark_info['name']) 175 all_real_time.append(benchmark_info['real_time']) 176 all_time_unit.append(benchmark_info['time_unit']) 177 all_cpu_time.append(benchmark_info['cpu_time']) 178 all_iterations.append(benchmark_info['iterations']) 179 classified_perf_info = {} 180 for module_name in module_categories: 181 module_perf_info = [] 182 for benchmark_info in self.perf_info: 183 if benchmark_info['test_name'].split('#')[0] == module_name: 184 module_perf_info.append(benchmark_info) 185 classified_perf_info[module_name] = module_perf_info 186 max_len = {'name': len(max(all_name, key=len)), 187 'real_time': len(max(all_real_time, key=len)), 188 'time_unit': len(max(all_time_unit, key=len)), 189 'cpu_time': len(max(all_cpu_time, key=len)), 190 'iterations': len(max(all_iterations, key=len))} 191 return classified_perf_info, max_len 192 193 194class RunStat: 195 """Class for storing stats of a test run.""" 196 197 def __init__(self, passed=0, failed=0, ignored=0, run_errors=False, 198 assumption_failed=0): 199 """Initialize a new instance of RunStat class. 200 201 Args: 202 passed: Count of passing tests. 203 failed: Count of failed tests. 204 ignored: Count of ignored tests. 205 assumption_failed: Count of assumption failure tests. 206 run_errors: A boolean if there were run errors 207 """ 208 # TODO(b/109822985): Track group and run estimated totals for updating 209 # summary line 210 self.passed = passed 211 self.failed = failed 212 self.ignored = ignored 213 self.assumption_failed = assumption_failed 214 self.perf_info = PerfInfo() 215 # Run errors are not for particular tests, they are runner errors. 216 self.run_errors = run_errors 217 218 @property 219 def total(self): 220 """Getter for total tests actually ran. Accessed via self.total""" 221 return self.passed + self.failed 222 223 224class ResultReporter: 225 """Result Reporter class. 226 227 As each test is run, the test runner will call self.process_test_result() 228 with a TestResult namedtuple that contains the following information: 229 - runner_name: Name of the test runner 230 - group_name: Name of the test group if any. 231 In Tradefed that's the Module name. 232 - test_name: Name of the test. 233 In Tradefed that's qualified.class#Method 234 - status: The strings FAILED or PASSED. 235 - stacktrace: The stacktrace if the test failed. 236 - group_total: The total tests scheduled to be run for a group. 237 In Tradefed this is provided when the Module starts. 238 - runner_total: The total tests scheduled to be run for the runner. 239 In Tradefed this is not available so is None. 240 241 The Result Reporter will print the results of this test and then update 242 its stats state. 243 244 Test stats are stored in the following structure: 245 - self.run_stats: Is RunStat instance containing stats for the overall run. 246 This include pass/fail counts across ALL test runners. 247 248 - self.runners: Is of the form: {RunnerName: {GroupName: RunStat Instance}} 249 Where {} is an ordered dict. 250 251 The stats instance contains stats for each test group. 252 If the runner doesn't support groups, then the group 253 name will be None. 254 255 For example this could be a state of ResultReporter: 256 257 run_stats: RunStat(passed:10, failed:5) 258 runners: {'AtestTradefedTestRunner': 259 {'Module1': RunStat(passed:1, failed:1), 260 'Module2': RunStat(passed:0, failed:4)}, 261 'RobolectricTestRunner': {None: RunStat(passed:5, failed:0)}, 262 'VtsTradefedTestRunner': {'Module1': RunStat(passed:4, failed:0)}} 263 """ 264 265 def __init__(self, silent=False, collect_only=False, flakes_info=False): 266 """Init ResultReporter. 267 268 Args: 269 silent: A boolean of silence or not. 270 """ 271 self.run_stats = RunStat() 272 self.runners = OrderedDict() 273 self.failed_tests = [] 274 self.all_test_results = [] 275 self.pre_test = None 276 self.log_path = None 277 self.silent = silent 278 self.rerun_options = '' 279 self.collect_only = collect_only 280 self.flakes_info = flakes_info 281 self.test_result_link = None 282 283 def process_test_result(self, test): 284 """Given the results of a single test, update stats and print results. 285 286 Args: 287 test: A TestResult namedtuple. 288 """ 289 if test.runner_name not in self.runners: 290 self.runners[test.runner_name] = OrderedDict() 291 assert self.runners[test.runner_name] != FAILURE_FLAG 292 self.all_test_results.append(test) 293 if test.group_name not in self.runners[test.runner_name]: 294 self.runners[test.runner_name][test.group_name] = RunStat() 295 self._print_group_title(test) 296 self._update_stats(test, 297 self.runners[test.runner_name][test.group_name]) 298 self._print_result(test) 299 300 def runner_failure(self, runner_name, failure_msg): 301 """Report a runner failure. 302 303 Use instead of process_test_result() when runner fails separate from 304 any particular test, e.g. during setup of runner. 305 306 Args: 307 runner_name: A string of the name of the runner. 308 failure_msg: A string of the failure message to pass to user. 309 """ 310 self.runners[runner_name] = FAILURE_FLAG 311 print('\n', runner_name, '\n', '-' * len(runner_name), sep='') 312 print('Runner encountered a critical failure. Skipping.\n' 313 'FAILURE: %s' % failure_msg) 314 315 def register_unsupported_runner(self, runner_name): 316 """Register an unsupported runner. 317 318 Prints the following to the screen: 319 320 RunnerName 321 ---------- 322 This runner does not support normal results formatting. 323 Below is the raw output of the test runner. 324 325 RAW OUTPUT: 326 <Raw Runner Output> 327 328 Args: 329 runner_name: A String of the test runner's name. 330 """ 331 assert runner_name not in self.runners 332 self.runners[runner_name] = UNSUPPORTED_FLAG 333 print('\n', runner_name, '\n', '-' * len(runner_name), sep='') 334 print('This runner does not support normal results formatting. Below ' 335 'is the raw output of the test runner.\n\nRAW OUTPUT:') 336 337 def print_starting_text(self): 338 """Print starting text for running tests.""" 339 print(au.colorize('\nRunning Tests...', constants.CYAN)) 340 341 def set_current_summary(self, run_num): 342 """Set current test summary to ITER_SUMMARY.""" 343 run_summary = [] 344 for runner_name, groups in self.runners.items(): 345 for group_name, stats in groups.items(): 346 name = group_name if group_name else runner_name 347 summary = self.process_summary(name, stats) 348 run_summary.append(summary) 349 summary_list = ITER_SUMMARY.get(run_num, []) 350 # Not contain redundant item 351 if not set(run_summary).issubset(set(summary_list)): 352 summary_list.extend(run_summary) 353 ITER_SUMMARY[run_num] = summary_list 354 355 # pylint: disable=too-many-branches 356 def print_summary(self): 357 """Print summary of all test runs. 358 359 Returns: 360 0 if all tests pass, non-zero otherwise. 361 362 """ 363 if self.collect_only: 364 return self.print_collect_tests() 365 tests_ret = constants.EXIT_CODE_SUCCESS 366 if not self.runners: 367 return tests_ret 368 print('\n{}'.format(au.colorize('Summary', constants.CYAN))) 369 print(au.delimiter('-', 7)) 370 iterations = len(ITER_SUMMARY) 371 for iter_num, summary_list in ITER_SUMMARY.items(): 372 if iterations > 1: 373 print(au.colorize("ITERATION %s" % (int(iter_num) + 1), 374 constants.BLUE)) 375 for summary in summary_list: 376 print(summary) 377 failed_sum = len(self.failed_tests) 378 for runner_name, groups in self.runners.items(): 379 if groups == UNSUPPORTED_FLAG: 380 print(runner_name, 'Unsupported. See raw output above.') 381 continue 382 if groups == FAILURE_FLAG: 383 tests_ret = constants.EXIT_CODE_TEST_FAILURE 384 print(runner_name, 'Crashed. No results to report.') 385 failed_sum += 1 386 continue 387 for group_name, stats in groups.items(): 388 name = group_name if group_name else runner_name 389 summary = self.process_summary(name, stats) 390 if stats.failed > 0: 391 tests_ret = constants.EXIT_CODE_TEST_FAILURE 392 if stats.run_errors: 393 tests_ret = constants.EXIT_CODE_TEST_FAILURE 394 failed_sum += 1 if not stats.failed else 0 395 if not ITER_SUMMARY: 396 print(summary) 397 self.run_stats.perf_info.print_perf_info() 398 print() 399 if tests_ret == constants.EXIT_CODE_SUCCESS: 400 print(au.colorize('All tests passed!', constants.GREEN)) 401 else: 402 message = '%d %s failed' % (failed_sum, 403 'tests' if failed_sum > 1 else 'test') 404 print(au.colorize(message, constants.RED)) 405 print('-'*len(message)) 406 self.print_failed_tests() 407 if self.log_path: 408 print('Test Logs have saved in %s' % self.log_path) 409 # TODO(b/174535786) Error handling while uploading test results has 410 # unexpected exceptions. 411 # TODO (b/174627499) Saving this information in atest history. 412 if self.test_result_link: 413 print('Test Result uploaded to %s' 414 % au.colorize(self.test_result_link, constants.GREEN)) 415 return tests_ret 416 417 def print_collect_tests(self): 418 """Print summary of collect tests only. 419 420 Returns: 421 0 if all tests collection done. 422 423 """ 424 tests_ret = constants.EXIT_CODE_SUCCESS 425 if not self.runners: 426 return tests_ret 427 print('\n{}'.format(au.colorize('Summary:' + constants.COLLECT_TESTS_ONLY, 428 constants.CYAN))) 429 print(au.delimiter('-', 26)) 430 for runner_name, groups in self.runners.items(): 431 for group_name, _ in groups.items(): 432 name = group_name if group_name else runner_name 433 print(name) 434 print() 435 if self.log_path: 436 print('Test Logs have saved in %s' % self.log_path) 437 return constants.EXIT_CODE_SUCCESS 438 439 def print_failed_tests(self): 440 """Print the failed tests if existed.""" 441 if self.failed_tests: 442 for test_name in self.failed_tests: 443 failed_details = test_name 444 if self.flakes_info: 445 flakes_method = test_name.replace('#', '.') 446 flakes_info = au.get_flakes(test_method=flakes_method) 447 if (flakes_info and 448 flakes_info.get(constants.FLAKE_PERCENT, None)): 449 failed_details += ( 450 ': flakes percent: {}%, flakes postsubmit per week:' 451 ' {}'.format(float(flakes_info.get( 452 constants.FLAKE_PERCENT)), 453 flakes_info.get( 454 constants.FLAKE_POSTSUBMIT, '0'))) 455 print(failed_details) 456 457 # pylint: disable=too-many-locals 458 def process_summary(self, name, stats): 459 """Process the summary line. 460 461 Strategy: 462 Error status happens -> 463 SomeTests: Passed: 2, Failed: 0 <red>(Completed With ERRORS)</red> 464 SomeTests: Passed: 2, <red>Failed</red>: 2 <red>(Completed With ERRORS)</red> 465 More than 1 test fails -> 466 SomeTests: Passed: 2, <red>Failed</red>: 5 467 No test fails -> 468 SomeTests: <green>Passed</green>: 2, Failed: 0 469 470 Args: 471 name: A string of test name. 472 stats: A RunStat instance for a test group. 473 474 Returns: 475 A summary of the test result. 476 """ 477 passed_label = 'Passed' 478 failed_label = 'Failed' 479 flakes_label = '' 480 ignored_label = 'Ignored' 481 assumption_failed_label = 'Assumption Failed' 482 error_label = '' 483 host_log_content = '' 484 flakes_percent = '' 485 if stats.failed > 0: 486 failed_label = au.colorize(failed_label, constants.RED) 487 mod_list = name.split() 488 module = '' 489 if len(mod_list) > 1: 490 module = mod_list[1] 491 if module and self.flakes_info: 492 flakes_info = au.get_flakes(test_module=module) 493 if (flakes_info and 494 flakes_info.get(constants.FLAKE_PERCENT, None)): 495 flakes_label = au.colorize('Flakes Percent:', 496 constants.RED) 497 flakes_percent = '{:.2f}%'.format(float(flakes_info.get( 498 constants.FLAKE_PERCENT))) 499 if stats.run_errors: 500 error_label = au.colorize('(Completed With ERRORS)', constants.RED) 501 # Only extract host_log_content if test name is tradefed 502 # Import here to prevent circular-import error. 503 from test_runners import atest_tf_test_runner 504 if name == atest_tf_test_runner.AtestTradefedTestRunner.NAME: 505 find_logs = au.find_files(self.log_path, 506 file_name=constants.TF_HOST_LOG) 507 if find_logs: 508 host_log_content = au.colorize( 509 '\n\nTradefederation host log:', constants.RED) 510 for tf_log_zip in find_logs: 511 host_log_content = host_log_content + au.extract_zip_text( 512 tf_log_zip) 513 elif stats.failed == 0: 514 passed_label = au.colorize(passed_label, constants.GREEN) 515 summary = ('%s: %s: %s, %s: %s, %s: %s, %s: %s, %s %s %s %s' 516 % (name, 517 passed_label, 518 stats.passed, 519 failed_label, 520 stats.failed, 521 ignored_label, 522 stats.ignored, 523 assumption_failed_label, 524 stats.assumption_failed, 525 flakes_label, 526 flakes_percent, 527 error_label, 528 host_log_content)) 529 return summary 530 531 def _update_stats(self, test, group): 532 """Given the results of a single test, update test run stats. 533 534 Args: 535 test: a TestResult namedtuple. 536 group: a RunStat instance for a test group. 537 """ 538 # TODO(109822985): Track group and run estimated totals for updating 539 # summary line 540 if test.status == test_runner_base.PASSED_STATUS: 541 self.run_stats.passed += 1 542 group.passed += 1 543 elif test.status == test_runner_base.IGNORED_STATUS: 544 self.run_stats.ignored += 1 545 group.ignored += 1 546 elif test.status == test_runner_base.ASSUMPTION_FAILED: 547 self.run_stats.assumption_failed += 1 548 group.assumption_failed += 1 549 elif test.status == test_runner_base.FAILED_STATUS: 550 self.run_stats.failed += 1 551 self.failed_tests.append(test.test_name) 552 group.failed += 1 553 elif test.status == test_runner_base.ERROR_STATUS: 554 self.run_stats.run_errors = True 555 group.run_errors = True 556 self.run_stats.perf_info.update_perf_info(test) 557 558 def _print_group_title(self, test): 559 """Print the title line for a test group. 560 561 Test Group/Runner Name 562 ---------------------- 563 564 Args: 565 test: A TestResult namedtuple. 566 """ 567 if self.silent: 568 return 569 title = test.group_name or test.runner_name 570 underline = '-' * (len(title)) 571 print('\n%s\n%s' % (title, underline)) 572 573 # pylint: disable=too-many-branches 574 def _print_result(self, test): 575 """Print the results of a single test. 576 577 Looks like: 578 fully.qualified.class#TestMethod: PASSED/FAILED 579 580 Args: 581 test: a TestResult namedtuple. 582 """ 583 if self.silent: 584 return 585 if not self.pre_test or (test.test_run_name != 586 self.pre_test.test_run_name): 587 print('%s (%s %s)' % (au.colorize(test.test_run_name, 588 constants.BLUE), 589 test.group_total, 590 'Test' if test.group_total <= 1 else 'Tests')) 591 if test.status == test_runner_base.ERROR_STATUS: 592 print('RUNNER ERROR: %s\n' % test.details) 593 self.pre_test = test 594 return 595 if test.test_name: 596 color = '' 597 if test.status == test_runner_base.PASSED_STATUS: 598 # Example of output: 599 # [78/92] test_name: PASSED (92ms) 600 color = constants.GREEN 601 elif test.status in (test_runner_base.IGNORED_STATUS, 602 test_runner_base.ASSUMPTION_FAILED): 603 # Example: [33/92] test_name: IGNORED (12ms) 604 # Example: [33/92] test_name: ASSUMPTION_FAILED (12ms) 605 color = constants.MAGENTA 606 else: 607 # Example: [26/92] test_name: FAILED (32ms) 608 color = constants.RED 609 print('[{}/{}] {}'.format(test.test_count, 610 test.group_total, 611 test.test_name), end='') 612 if self.collect_only: 613 print() 614 else: 615 print(': {} {}'.format(au.colorize(test.status, color), 616 test.test_time)) 617 if test.status == test_runner_base.PASSED_STATUS: 618 for key, data in test.additional_info.items(): 619 if key not in BENCHMARK_EVENT_KEYS: 620 print('\t%s: %s' % (au.colorize(key, constants.BLUE), 621 data)) 622 if test.status == test_runner_base.FAILED_STATUS: 623 print('\nSTACKTRACE:\n%s' % test.details) 624 self.pre_test = test 625