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