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