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=line-too-long
16
17"""
18Result Reporter
19
20The result reporter formats and prints test results.
21
22----
23Example Output for command to run following tests:
24CtsAnimationTestCases:EvaluatorTest, HelloWorldTests, and WmTests
25
26Running Tests ...
27
28CtsAnimationTestCases
29---------------------
30
31android.animation.cts.EvaluatorTest.UnitTests (7 Tests)
32[1/7] android.animation.cts.EvaluatorTest#testRectEvaluator: PASSED (153ms)
33[2/7] android.animation.cts.EvaluatorTest#testIntArrayEvaluator: PASSED (0ms)
34[3/7] android.animation.cts.EvaluatorTest#testIntEvaluator: PASSED (0ms)
35[4/7] android.animation.cts.EvaluatorTest#testFloatArrayEvaluator: PASSED (1ms)
36[5/7] android.animation.cts.EvaluatorTest#testPointFEvaluator: PASSED (1ms)
37[6/7] android.animation.cts.EvaluatorTest#testArgbEvaluator: PASSED (0ms)
38[7/7] android.animation.cts.EvaluatorTest#testFloatEvaluator: PASSED (1ms)
39
40HelloWorldTests
41---------------
42
43android.test.example.helloworld.UnitTests(2 Tests)
44[1/2] android.test.example.helloworld.HelloWorldTest#testHalloWelt: PASSED (0ms)
45[2/2] android.test.example.helloworld.HelloWorldTest#testHelloWorld: PASSED (1ms)
46
47WmTests
48-------
49
50com.android.tradefed.targetprep.UnitTests (1 Test)
51RUNNER ERROR: com.android.tradefed.targetprep.TargetSetupError:
52Failed to install WmTests.apk on 127.0.0.1:54373. Reason:
53    error message ...
54
55
56Summary
57-------
58CtsAnimationTestCases: Passed: 7, Failed: 0
59HelloWorldTests: Passed: 2, Failed: 0
60WmTests: Passed: 0, Failed: 0 (Completed With ERRORS)
61
621 test failed
63"""
64
65from __future__ import print_function
66
67from collections import OrderedDict
68
69import constants
70import atest_utils as au
71
72from test_runners import test_runner_base
73
74UNSUPPORTED_FLAG = 'UNSUPPORTED_RUNNER'
75FAILURE_FLAG = 'RUNNER_FAILURE'
76BENCHMARK_ESSENTIAL_KEYS = {'repetition_index', 'cpu_time', 'name', 'repetitions',
77                            'run_type', 'threads', 'time_unit', 'iterations',
78                            'run_name', 'real_time'}
79# TODO(b/146875480): handle the optional benchmark events
80BENCHMARK_OPTIONAL_KEYS = {'bytes_per_second', 'label'}
81BENCHMARK_EVENT_KEYS = BENCHMARK_ESSENTIAL_KEYS.union(BENCHMARK_OPTIONAL_KEYS)
82INT_KEYS = {'cpu_time', 'real_time'}
83
84class PerfInfo():
85    """Class for storing performance test of a test run."""
86
87    def __init__(self):
88        """Initialize a new instance of PerfInfo class."""
89        # perf_info: A list of benchmark_info(dict).
90        self.perf_info = []
91
92    def update_perf_info(self, test):
93        """Update perf_info with the given result of a single test.
94
95        Args:
96            test: A TestResult namedtuple.
97        """
98        all_additional_keys = set(test.additional_info.keys())
99        # Ensure every key is in all_additional_keys.
100        if not BENCHMARK_ESSENTIAL_KEYS.issubset(all_additional_keys):
101            return
102        benchmark_info = {}
103        benchmark_info['test_name'] = test.test_name
104        for key, data in test.additional_info.items():
105            if key in INT_KEYS:
106                data_to_int = data.split('.')[0]
107                benchmark_info[key] = data_to_int
108            elif key in BENCHMARK_EVENT_KEYS:
109                benchmark_info[key] = data
110        if benchmark_info:
111            self.perf_info.append(benchmark_info)
112
113    def print_perf_info(self):
114        """Print summary of a perf_info."""
115        if not self.perf_info:
116            return
117        classify_perf_info, max_len = self._classify_perf_info()
118        separator = '-' * au.get_terminal_size()[0]
119        print(separator)
120        print("{:{name}}    {:^{real_time}}    {:^{cpu_time}}    "
121              "{:>{iterations}}".format(
122                  'Benchmark', 'Time', 'CPU', 'Iteration',
123                  name=max_len['name']+3,
124                  real_time=max_len['real_time']+max_len['time_unit']+1,
125                  cpu_time=max_len['cpu_time']+max_len['time_unit']+1,
126                  iterations=max_len['iterations']))
127        print(separator)
128        for module_name, module_perf_info in classify_perf_info.items():
129            print("{}:".format(module_name))
130            for benchmark_info in module_perf_info:
131                # BpfBenchMark/MapWriteNewEntry/1    1530 ns     1522 ns   460517
132                print("  #{:{name}}    {:>{real_time}} {:{time_unit}}    "
133                      "{:>{cpu_time}} {:{time_unit}}    "
134                      "{:>{iterations}}".format(benchmark_info['name'],
135                                                benchmark_info['real_time'],
136                                                benchmark_info['time_unit'],
137                                                benchmark_info['cpu_time'],
138                                                benchmark_info['time_unit'],
139                                                benchmark_info['iterations'],
140                                                name=max_len['name'],
141                                                real_time=max_len['real_time'],
142                                                time_unit=max_len['time_unit'],
143                                                cpu_time=max_len['cpu_time'],
144                                                iterations=max_len['iterations']))
145
146    def _classify_perf_info(self):
147        """Classify the perf_info by test module name.
148
149        Returns:
150            A tuple of (classified_perf_info, max_len), where
151            classified_perf_info: A dict of perf_info and each perf_info are
152                                 belong to different modules.
153                e.g.
154                    { module_name_01: [perf_info of module_1],
155                      module_name_02: [perf_info of module_2], ...}
156            max_len: A dict which stores the max length of each event.
157                     It contains the max string length of 'name', real_time',
158                     'time_unit', 'cpu_time', 'iterations'.
159                e.g.
160                    {name: 56, real_time: 9, time_unit: 2, cpu_time: 8,
161                     iterations: 12}
162        """
163        module_categories = set()
164        max_len = {}
165        all_name = []
166        all_real_time = []
167        all_time_unit = []
168        all_cpu_time = []
169        all_iterations = ['Iteration']
170        for benchmark_info in self.perf_info:
171            module_categories.add(benchmark_info['test_name'].split('#')[0])
172            all_name.append(benchmark_info['name'])
173            all_real_time.append(benchmark_info['real_time'])
174            all_time_unit.append(benchmark_info['time_unit'])
175            all_cpu_time.append(benchmark_info['cpu_time'])
176            all_iterations.append(benchmark_info['iterations'])
177        classified_perf_info = {}
178        for module_name in module_categories:
179            module_perf_info = []
180            for benchmark_info in self.perf_info:
181                if benchmark_info['test_name'].split('#')[0] == module_name:
182                    module_perf_info.append(benchmark_info)
183            classified_perf_info[module_name] = module_perf_info
184        max_len = {'name': len(max(all_name, key=len)),
185                   'real_time': len(max(all_real_time, key=len)),
186                   'time_unit': len(max(all_time_unit, key=len)),
187                   'cpu_time': len(max(all_cpu_time, key=len)),
188                   'iterations': len(max(all_iterations, key=len))}
189        return classified_perf_info, max_len
190
191
192class RunStat:
193    """Class for storing stats of a test run."""
194
195    def __init__(self, passed=0, failed=0, ignored=0, run_errors=False,
196                 assumption_failed=0):
197        """Initialize a new instance of RunStat class.
198
199        Args:
200            passed: Count of passing tests.
201            failed: Count of failed tests.
202            ignored: Count of ignored tests.
203            assumption_failed: Count of assumption failure tests.
204            run_errors: A boolean if there were run errors
205        """
206        # TODO(b/109822985): Track group and run estimated totals for updating
207        # summary line
208        self.passed = passed
209        self.failed = failed
210        self.ignored = ignored
211        self.assumption_failed = assumption_failed
212        self.perf_info = PerfInfo()
213        # Run errors are not for particular tests, they are runner errors.
214        self.run_errors = run_errors
215
216    @property
217    def total(self):
218        """Getter for total tests actually ran. Accessed via self.total"""
219        return self.passed + self.failed
220
221
222class ResultReporter:
223    """Result Reporter class.
224
225    As each test is run, the test runner will call self.process_test_result()
226    with a TestResult namedtuple that contains the following information:
227    - runner_name:   Name of the test runner
228    - group_name:    Name of the test group if any.
229                     In Tradefed that's the Module name.
230    - test_name:     Name of the test.
231                     In Tradefed that's qualified.class#Method
232    - status:        The strings FAILED or PASSED.
233    - stacktrace:    The stacktrace if the test failed.
234    - group_total:   The total tests scheduled to be run for a group.
235                     In Tradefed this is provided when the Module starts.
236    - runner_total:  The total tests scheduled to be run for the runner.
237                     In Tradefed this is not available so is None.
238
239    The Result Reporter will print the results of this test and then update
240    its stats state.
241
242    Test stats are stored in the following structure:
243    - self.run_stats: Is RunStat instance containing stats for the overall run.
244                      This include pass/fail counts across ALL test runners.
245
246    - self.runners:  Is of the form: {RunnerName: {GroupName: RunStat Instance}}
247                     Where {} is an ordered dict.
248
249                     The stats instance contains stats for each test group.
250                     If the runner doesn't support groups, then the group
251                     name will be None.
252
253    For example this could be a state of ResultReporter:
254
255    run_stats: RunStat(passed:10, failed:5)
256    runners: {'AtestTradefedTestRunner':
257                            {'Module1': RunStat(passed:1, failed:1),
258                             'Module2': RunStat(passed:0, failed:4)},
259              'RobolectricTestRunner': {None: RunStat(passed:5, failed:0)},
260              'VtsTradefedTestRunner': {'Module1': RunStat(passed:4, failed:0)}}
261    """
262
263    def __init__(self, silent=False):
264        """Init ResultReporter.
265
266        Args:
267            silent: A boolean of silence or not.
268        """
269        self.run_stats = RunStat()
270        self.runners = OrderedDict()
271        self.failed_tests = []
272        self.all_test_results = []
273        self.pre_test = None
274        self.log_path = None
275        self.silent = silent
276        self.rerun_options = ''
277
278    def process_test_result(self, test):
279        """Given the results of a single test, update stats and print results.
280
281        Args:
282            test: A TestResult namedtuple.
283        """
284        if test.runner_name not in self.runners:
285            self.runners[test.runner_name] = OrderedDict()
286        assert self.runners[test.runner_name] != FAILURE_FLAG
287        self.all_test_results.append(test)
288        if test.group_name not in self.runners[test.runner_name]:
289            self.runners[test.runner_name][test.group_name] = RunStat()
290            self._print_group_title(test)
291        self._update_stats(test,
292                           self.runners[test.runner_name][test.group_name])
293        self._print_result(test)
294
295    def runner_failure(self, runner_name, failure_msg):
296        """Report a runner failure.
297
298        Use instead of process_test_result() when runner fails separate from
299        any particular test, e.g. during setup of runner.
300
301        Args:
302            runner_name: A string of the name of the runner.
303            failure_msg: A string of the failure message to pass to user.
304        """
305        self.runners[runner_name] = FAILURE_FLAG
306        print('\n', runner_name, '\n', '-' * len(runner_name), sep='')
307        print('Runner encountered a critical failure. Skipping.\n'
308              'FAILURE: %s' % failure_msg)
309
310    def register_unsupported_runner(self, runner_name):
311        """Register an unsupported runner.
312
313           Prints the following to the screen:
314
315           RunnerName
316           ----------
317           This runner does not support normal results formatting.
318           Below is the raw output of the test runner.
319
320           RAW OUTPUT:
321           <Raw Runner Output>
322
323           Args:
324              runner_name: A String of the test runner's name.
325        """
326        assert runner_name not in self.runners
327        self.runners[runner_name] = UNSUPPORTED_FLAG
328        print('\n', runner_name, '\n', '-' * len(runner_name), sep='')
329        print('This runner does not support normal results formatting. Below '
330              'is the raw output of the test runner.\n\nRAW OUTPUT:')
331
332    def print_starting_text(self):
333        """Print starting text for running tests."""
334        print(au.colorize('\nRunning Tests...', constants.CYAN))
335
336    def print_summary(self, is_collect_tests_only=False):
337        """Print summary of all test runs.
338
339        Args:
340            is_collect_tests_only: A boolean of collect_tests_only.
341
342        Returns:
343            0 if all tests pass, non-zero otherwise.
344
345        """
346        if is_collect_tests_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                print('%s' % test_name)
415
416    def process_summary(self, name, stats):
417        """Process the summary line.
418
419        Strategy:
420            Error status happens ->
421                SomeTests: Passed: 2, Failed: 0 <red>(Completed With ERRORS)</red>
422                SomeTests: Passed: 2, <red>Failed</red>: 2 <red>(Completed With ERRORS)</red>
423            More than 1 test fails ->
424                SomeTests: Passed: 2, <red>Failed</red>: 5
425            No test fails ->
426                SomeTests: <green>Passed</green>: 2, Failed: 0
427
428        Args:
429            name: A string of test name.
430            stats: A RunStat instance for a test group.
431
432        Returns:
433            A summary of the test result.
434        """
435        passed_label = 'Passed'
436        failed_label = 'Failed'
437        ignored_label = 'Ignored'
438        assumption_failed_label = 'Assumption Failed'
439        error_label = ''
440        if stats.failed > 0:
441            failed_label = au.colorize(failed_label, constants.RED)
442        if stats.run_errors:
443            error_label = au.colorize('(Completed With ERRORS)', constants.RED)
444        elif stats.failed == 0:
445            passed_label = au.colorize(passed_label, constants.GREEN)
446        summary = '%s: %s: %s, %s: %s, %s: %s, %s: %s %s' % (name,
447                                                             passed_label,
448                                                             stats.passed,
449                                                             failed_label,
450                                                             stats.failed,
451                                                             ignored_label,
452                                                             stats.ignored,
453                                                             assumption_failed_label,
454                                                             stats.assumption_failed,
455                                                             error_label)
456        return summary
457
458    def _update_stats(self, test, group):
459        """Given the results of a single test, update test run stats.
460
461        Args:
462            test: a TestResult namedtuple.
463            group: a RunStat instance for a test group.
464        """
465        # TODO(109822985): Track group and run estimated totals for updating
466        # summary line
467        if test.status == test_runner_base.PASSED_STATUS:
468            self.run_stats.passed += 1
469            group.passed += 1
470        elif test.status == test_runner_base.IGNORED_STATUS:
471            self.run_stats.ignored += 1
472            group.ignored += 1
473        elif test.status == test_runner_base.ASSUMPTION_FAILED:
474            self.run_stats.assumption_failed += 1
475            group.assumption_failed += 1
476        elif test.status == test_runner_base.FAILED_STATUS:
477            self.run_stats.failed += 1
478            self.failed_tests.append(test.test_name)
479            group.failed += 1
480        elif test.status == test_runner_base.ERROR_STATUS:
481            self.run_stats.run_errors = True
482            group.run_errors = True
483        self.run_stats.perf_info.update_perf_info(test)
484
485    def _print_group_title(self, test):
486        """Print the title line for a test group.
487
488        Test Group/Runner Name
489        ----------------------
490
491        Args:
492            test: A TestResult namedtuple.
493        """
494        if self.silent:
495            return
496        title = test.group_name or test.runner_name
497        underline = '-' * (len(title))
498        print('\n%s\n%s' % (title, underline))
499
500    def _print_result(self, test):
501        """Print the results of a single test.
502
503           Looks like:
504           fully.qualified.class#TestMethod: PASSED/FAILED
505
506        Args:
507            test: a TestResult namedtuple.
508        """
509        if self.silent:
510            return
511        if not self.pre_test or (test.test_run_name !=
512                                 self.pre_test.test_run_name):
513            print('%s (%s %s)' % (au.colorize(test.test_run_name,
514                                              constants.BLUE),
515                                  test.group_total,
516                                  'Test' if test.group_total <= 1 else 'Tests'))
517        if test.status == test_runner_base.ERROR_STATUS:
518            print('RUNNER ERROR: %s\n' % test.details)
519            self.pre_test = test
520            return
521        if test.test_name:
522            if test.status == test_runner_base.PASSED_STATUS:
523                # Example of output:
524                # [78/92] test_name: PASSED (92ms)
525                print('[%s/%s] %s: %s %s' % (test.test_count,
526                                             test.group_total,
527                                             test.test_name,
528                                             au.colorize(
529                                                 test.status,
530                                                 constants.GREEN),
531                                             test.test_time))
532                for key, data in test.additional_info.items():
533                    if key not in BENCHMARK_EVENT_KEYS:
534                        print('\t%s: %s' % (au.colorize(key, constants.BLUE), data))
535            elif test.status == test_runner_base.IGNORED_STATUS:
536                # Example: [33/92] test_name: IGNORED (12ms)
537                print('[%s/%s] %s: %s %s' % (test.test_count, test.group_total,
538                                             test.test_name, au.colorize(
539                                                 test.status, constants.MAGENTA),
540                                             test.test_time))
541            elif test.status == test_runner_base.ASSUMPTION_FAILED:
542                # Example: [33/92] test_name: ASSUMPTION_FAILED (12ms)
543                print('[%s/%s] %s: %s %s' % (test.test_count, test.group_total,
544                                             test.test_name, au.colorize(
545                                                 test.status, constants.MAGENTA),
546                                             test.test_time))
547            else:
548                # Example: [26/92] test_name: FAILED (32ms)
549                print('[%s/%s] %s: %s %s' % (test.test_count, test.group_total,
550                                             test.test_name, au.colorize(
551                                                 test.status, constants.RED),
552                                             test.test_time))
553        if test.status == test_runner_base.FAILED_STATUS:
554            print('\nSTACKTRACE:\n%s' % test.details)
555        self.pre_test = test
556