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