1# Copyright 2019, 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"""Atest test event handler class."""
16
17# pylint: disable=line-too-long
18
19from __future__ import print_function
20
21import time
22import logging
23
24from collections import deque
25from datetime import timedelta
26
27import atest_execution_info
28import result_reporter
29
30from test_runners import test_runner_base
31
32
33EVENT_NAMES = {'module_started': 'TEST_MODULE_STARTED',
34               'module_ended': 'TEST_MODULE_ENDED',
35               'run_started': 'TEST_RUN_STARTED',
36               'run_ended': 'TEST_RUN_ENDED',
37               # Next three are test-level events
38               'test_started': 'TEST_STARTED',
39               'test_failed': 'TEST_FAILED',
40               'test_ended': 'TEST_ENDED',
41               # Last two failures are runner-level, not test-level.
42               # Invocation failure is broader than run failure.
43               'run_failed': 'TEST_RUN_FAILED',
44               'invocation_failed': 'INVOCATION_FAILED',
45               'test_ignored': 'TEST_IGNORED',
46               'test_assumption_failure': 'TEST_ASSUMPTION_FAILURE',
47               'log_association': 'LOG_ASSOCIATION'}
48
49EVENT_PAIRS = {EVENT_NAMES['module_started']: EVENT_NAMES['module_ended'],
50               EVENT_NAMES['run_started']: EVENT_NAMES['run_ended'],
51               EVENT_NAMES['test_started']: EVENT_NAMES['test_ended']}
52START_EVENTS = list(EVENT_PAIRS.keys())
53END_EVENTS = list(EVENT_PAIRS.values())
54TEST_NAME_TEMPLATE = '%s#%s'
55EVENTS_NOT_BALANCED = ('Error: Saw %s Start event and %s End event. These '
56                       'should be equal!')
57
58# time in millisecond.
59ONE_SECOND = 1000
60ONE_MINUTE = 60000
61ONE_HOUR = 3600000
62
63CONNECTION_STATE = {
64    'current_test': None,
65    'test_run_name': None,
66    'last_failed': None,
67    'last_ignored': None,
68    'last_assumption_failed': None,
69    'current_group': None,
70    'current_group_total': None,
71    'test_count': 0,
72    'test_start_time': None}
73
74class EventHandleError(Exception):
75    """Raised when handle event error."""
76
77class EventHandler:
78    """Test Event handle class."""
79
80    def __init__(self, reporter, name):
81        self.reporter = reporter
82        self.runner_name = name
83        self.state = CONNECTION_STATE.copy()
84        self.event_stack = deque()
85        self.log_associations = []
86        self.run_num = 0
87
88    def _module_started(self, event_data):
89        if atest_execution_info.PREPARE_END_TIME is None:
90            atest_execution_info.PREPARE_END_TIME = time.time()
91        self.state['current_group'] = event_data['moduleName']
92        self.state['last_failed'] = None
93        self.state['current_test'] = None
94
95    def _run_started(self, event_data):
96        # Technically there can be more than one run per module.
97        self.run_num = event_data.get('runAttempt', 0)
98        self.state['test_run_name'] = event_data.setdefault('runName', '')
99        self.state['current_group_total'] = event_data['testCount']
100        self.state['test_count'] = 0
101        self.state['last_failed'] = None
102        self.state['current_test'] = None
103
104    def _test_started(self, event_data):
105        name = TEST_NAME_TEMPLATE % (event_data['className'],
106                                     event_data['testName'])
107        self.state['current_test'] = name
108        self.state['test_count'] += 1
109        self.state['test_start_time'] = event_data['start_time']
110
111    def _test_failed(self, event_data):
112        self.state['last_failed'] = {'name': TEST_NAME_TEMPLATE % (
113            event_data['className'],
114            event_data['testName']),
115                                     'trace': event_data['trace']}
116
117    def _test_ignored(self, event_data):
118        name = TEST_NAME_TEMPLATE % (event_data['className'],
119                                     event_data['testName'])
120        self.state['last_ignored'] = name
121
122    def _test_assumption_failure(self, event_data):
123        name = TEST_NAME_TEMPLATE % (event_data['className'],
124                                     event_data['testName'])
125        self.state['last_assumption_failed'] = name
126
127    def _run_failed(self, event_data):
128        # Module and Test Run probably started, but failure occurred.
129        self.reporter.process_test_result(test_runner_base.TestResult(
130            runner_name=self.runner_name,
131            group_name=self.state['current_group'],
132            test_name=self.state['current_test'],
133            status=test_runner_base.ERROR_STATUS,
134            details=event_data['reason'],
135            test_count=self.state['test_count'],
136            test_time='',
137            runner_total=None,
138            group_total=self.state['current_group_total'],
139            additional_info={},
140            test_run_name=self.state['test_run_name']))
141
142    def _invocation_failed(self, event_data):
143        # Broadest possible failure. May not even start the module/test run.
144        self.reporter.process_test_result(test_runner_base.TestResult(
145            runner_name=self.runner_name,
146            group_name=self.state['current_group'],
147            test_name=self.state['current_test'],
148            status=test_runner_base.ERROR_STATUS,
149            details=event_data['cause'],
150            test_count=self.state['test_count'],
151            test_time='',
152            runner_total=None,
153            group_total=self.state['current_group_total'],
154            additional_info={},
155            test_run_name=self.state['test_run_name']))
156
157    # pylint: disable=unused-argument
158    def _run_ended(self, event_data):
159        # Renew ResultReport if is module level(reporter.silent=False)
160        if not self.reporter.silent:
161            self.reporter.set_current_summary(self.run_num)
162            self.reporter = result_reporter.ResultReporter(silent=False)
163
164    def _module_ended(self, event_data):
165        pass
166
167    def _test_ended(self, event_data):
168        name = TEST_NAME_TEMPLATE % (event_data['className'],
169                                     event_data['testName'])
170        test_time = ''
171        if self.state['test_start_time']:
172            test_time = self._calc_duration(event_data['end_time'] -
173                                            self.state['test_start_time'])
174        if self.state['last_failed'] and name == self.state['last_failed']['name']:
175            status = test_runner_base.FAILED_STATUS
176            trace = self.state['last_failed']['trace']
177            self.state['last_failed'] = None
178        elif (self.state['last_assumption_failed'] and
179              name == self.state['last_assumption_failed']):
180            status = test_runner_base.ASSUMPTION_FAILED
181            self.state['last_assumption_failed'] = None
182            trace = None
183        elif self.state['last_ignored'] and name == self.state['last_ignored']:
184            status = test_runner_base.IGNORED_STATUS
185            self.state['last_ignored'] = None
186            trace = None
187        else:
188            status = test_runner_base.PASSED_STATUS
189            trace = None
190
191        default_event_keys = ['className', 'end_time', 'testName']
192        additional_info = {}
193        for event_key in event_data.keys():
194            if event_key not in default_event_keys:
195                additional_info[event_key] = event_data.get(event_key, None)
196
197        self.reporter.process_test_result(test_runner_base.TestResult(
198            runner_name=self.runner_name,
199            group_name=self.state['current_group'],
200            test_name=name,
201            status=status,
202            details=trace,
203            test_count=self.state['test_count'],
204            test_time=test_time,
205            runner_total=None,
206            additional_info=additional_info,
207            group_total=self.state['current_group_total'],
208            test_run_name=self.state['test_run_name']))
209
210    def _log_association(self, event_data):
211        event_data.setdefault('time', time.time())
212        self.log_associations.append(event_data)
213
214    switch_handler = {EVENT_NAMES['module_started']: _module_started,
215                      EVENT_NAMES['run_started']: _run_started,
216                      EVENT_NAMES['test_started']: _test_started,
217                      EVENT_NAMES['test_failed']: _test_failed,
218                      EVENT_NAMES['test_ignored']: _test_ignored,
219                      EVENT_NAMES['test_assumption_failure']: _test_assumption_failure,
220                      EVENT_NAMES['run_failed']: _run_failed,
221                      EVENT_NAMES['invocation_failed']: _invocation_failed,
222                      EVENT_NAMES['test_ended']: _test_ended,
223                      EVENT_NAMES['run_ended']: _run_ended,
224                      EVENT_NAMES['module_ended']: _module_ended,
225                      EVENT_NAMES['log_association']: _log_association}
226
227    def process_event(self, event_name, event_data):
228        """Process the events of the test run and call reporter with results.
229
230        Args:
231            event_name: A string of the event name.
232            event_data: A dict of event data.
233        """
234        logging.debug('Processing %s %s', event_name, event_data)
235        if event_name in START_EVENTS:
236            self.event_stack.append(event_name)
237        elif event_name in END_EVENTS:
238            self._check_events_are_balanced(event_name, self.reporter)
239        if event_name in self.switch_handler:
240            self.switch_handler[event_name](self, event_data)
241        else:
242            # TODO(b/128875503): Implement the mechanism to inform not handled
243            # TF event.
244            logging.debug('Event[%s] is not processable.', event_name)
245
246    def _check_events_are_balanced(self, event_name, reporter):
247        """Check Start events and End events. They should be balanced.
248
249        If they are not balanced, print the error message in
250        state['last_failed'], then raise TradeFedExitError.
251
252        Args:
253            event_name: A string of the event name.
254            reporter: A ResultReporter instance.
255        Raises:
256            TradeFedExitError if we doesn't have a balance of START/END events.
257        """
258        start_event = self.event_stack.pop() if self.event_stack else None
259        if not start_event or EVENT_PAIRS[start_event] != event_name:
260            # Here bubble up the failed trace in the situation having
261            # TEST_FAILED but never receiving TEST_ENDED.
262            if self.state['last_failed'] and (start_event ==
263                                              EVENT_NAMES['test_started']):
264                reporter.process_test_result(test_runner_base.TestResult(
265                    runner_name=self.runner_name,
266                    group_name=self.state['current_group'],
267                    test_name=self.state['last_failed']['name'],
268                    status=test_runner_base.FAILED_STATUS,
269                    details=self.state['last_failed']['trace'],
270                    test_count=self.state['test_count'],
271                    test_time='',
272                    runner_total=None,
273                    group_total=self.state['current_group_total'],
274                    additional_info={},
275                    test_run_name=self.state['test_run_name']))
276            raise EventHandleError(EVENTS_NOT_BALANCED % (start_event,
277                                                          event_name))
278
279    @staticmethod
280    def _calc_duration(duration):
281        """Convert duration from ms to 3h2m43.034s.
282
283        Args:
284            duration: millisecond
285
286        Returns:
287            string in h:m:s, m:s, s or millis, depends on the duration.
288        """
289        delta = timedelta(milliseconds=duration)
290        timestamp = str(delta).split(':')  # hh:mm:microsec
291
292        if duration < ONE_SECOND:
293            return "({}ms)".format(duration)
294        if duration < ONE_MINUTE:
295            return "({:.3f}s)".format(float(timestamp[2]))
296        if duration < ONE_HOUR:
297            return "({0}m{1:.3f}s)".format(timestamp[1], float(timestamp[2]))
298        return "({0}h{1}m{2:.3f}s)".format(timestamp[0],
299                                           timestamp[1], float(timestamp[2]))
300