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