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