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