1# Copyright 2018 The Chromium OS Authors. All rights reserved. 2# Use of this source code is governed by a BSD-style license that can be 3# found in the LICENSE file. 4 5import datetime 6import logging 7import os 8import re 9import shutil 10import time 11 12from autotest_lib.client.common_lib import error 13from autotest_lib.client.common_lib import utils 14 15 16_DEFAULT_RUN = utils.run 17_DEFAULT_COPY = shutil.copy 18 19class UpdateEngineUtil(object): 20 """Utility code shared between client and server update_engine autotests""" 21 22 # Update engine status lines. 23 _LAST_CHECKED_TIME = 'LAST_CHECKED_TIME' 24 _PROGRESS = 'PROGRESS' 25 _CURRENT_OP = 'CURRENT_OP' 26 _NEW_VERSION = 'NEW VERSION' 27 _NEW_SIZE = 'NEW_SIZE' 28 29 # Update engine statuses. 30 _UPDATE_STATUS_IDLE = 'UPDATE_STATUS_IDLE' 31 _UPDATE_ENGINE_DOWNLOADING = 'UPDATE_STATUS_DOWNLOADING' 32 _UPDATE_ENGINE_FINALIZING = 'UPDATE_STATUS_FINALIZING' 33 _UPDATE_STATUS_UPDATED_NEED_REBOOT = 'UPDATE_STATUS_UPDATED_NEED_REBOOT' 34 _UPDATE_STATUS_REPORTING_ERROR_EVENT = 'UPDATE_STATUS_REPORTING_ERROR_EVENT' 35 36 # Files used by the tests. 37 _UPDATE_ENGINE_LOG = '/var/log/update_engine.log' 38 _UPDATE_ENGINE_LOG_DIR = '/var/log/update_engine/' 39 _CUSTOM_LSB_RELEASE = '/mnt/stateful_partition/etc/lsb-release' 40 _UPDATE_ENGINE_PREFS_DIR = '/var/lib/update_engine/prefs/' 41 42 # Public key used to force update_engine to verify omaha response data on 43 # test images. 44 _IMAGE_PUBLIC_KEY = 'LS0tLS1CRUdJTiBQVUJMSUMgS0VZLS0tLS0KTUlJQklqQU5CZ2txaGtpRzl3MEJBUUVGQUFPQ0FROEFNSUlCQ2dLQ0FRRUFxZE03Z25kNDNjV2ZRenlydDE2UQpESEUrVDB5eGcxOE9aTys5c2M4aldwakMxekZ0b01Gb2tFU2l1OVRMVXArS1VDMjc0ZitEeElnQWZTQ082VTVECkpGUlBYVXp2ZTF2YVhZZnFsalVCeGMrSlljR2RkNlBDVWw0QXA5ZjAyRGhrckduZi9ya0hPQ0VoRk5wbTUzZG8Kdlo5QTZRNUtCZmNnMUhlUTA4OG9wVmNlUUd0VW1MK2JPTnE1dEx2TkZMVVUwUnUwQW00QURKOFhtdzRycHZxdgptWEphRm1WdWYvR3g3K1RPbmFKdlpUZU9POUFKSzZxNlY4RTcrWlppTUljNUY0RU9zNUFYL2xaZk5PM1JWZ0cyCk83RGh6emErbk96SjNaSkdLNVI0V3daZHVobjlRUllvZ1lQQjBjNjI4NzhxWHBmMkJuM05wVVBpOENmL1JMTU0KbVFJREFRQUIKLS0tLS1FTkQgUFVCTElDIEtFWS0tLS0tCg==' 45 46 47 def __init__(self, run_func=_DEFAULT_RUN, get_file=_DEFAULT_COPY): 48 """ 49 Initialize this class. 50 51 @param run_func: the function to use to run commands on the client. 52 Defaults for use by client tests, but can be 53 overwritten to run remotely from a server test. 54 @param get_file: the function to use when copying a file. Defaults 55 for use by client tests. Called with 56 (file, destination) syntax. 57 58 """ 59 self._create_update_engine_variables(run_func, get_file) 60 61 62 def _create_update_engine_variables(self, run_func=_DEFAULT_RUN, 63 get_file=_DEFAULT_COPY): 64 """See __init__().""" 65 self._run = run_func 66 self._get_file = get_file 67 68 69 def _wait_for_progress(self, progress): 70 """ 71 Waits until we reach the percentage passed as the input. 72 73 @param progress: The progress [0.0 .. 1.0] we want to wait for. 74 """ 75 while True: 76 completed = self._get_update_progress() 77 logging.debug('Checking if %s is greater than %s', completed, 78 progress) 79 if completed >= progress: 80 break 81 time.sleep(1) 82 83 84 def _is_update_started(self): 85 """Checks if the update has started.""" 86 status = self._get_update_engine_status() 87 if status is None: 88 return False 89 return any(arg == status[self._CURRENT_OP] for arg in 90 [self._UPDATE_ENGINE_DOWNLOADING, self._UPDATE_ENGINE_FINALIZING]) 91 92 93 def _get_update_progress(self): 94 """Returns the current payload downloaded progress.""" 95 while True: 96 status = self._get_update_engine_status() 97 if not status: 98 continue 99 if self._UPDATE_STATUS_IDLE == status[self._CURRENT_OP]: 100 err_str = self._get_last_error_string() 101 raise error.TestFail('Update status was idle while trying to ' 102 'get download status. Last error: %s' % 103 err_str) 104 if self._UPDATE_STATUS_REPORTING_ERROR_EVENT == status[ 105 self._CURRENT_OP]: 106 err_str = self._get_last_error_string() 107 raise error.TestFail('Update status reported error: %s' % 108 err_str) 109 if self._UPDATE_STATUS_UPDATED_NEED_REBOOT == status[ 110 self._CURRENT_OP]: 111 raise error.TestFail('Update status was NEEDS_REBOOT while ' 112 'trying to get download status.') 113 # If we call this right after reboot it may not be downloading yet. 114 if self._UPDATE_ENGINE_DOWNLOADING != status[self._CURRENT_OP]: 115 time.sleep(1) 116 continue 117 return float(status[self._PROGRESS]) 118 119 120 def _wait_for_update_to_fail(self): 121 """Waits for the update to retry until failure.""" 122 timeout_minutes = 20 123 timeout = time.time() + 60 * timeout_minutes 124 while True: 125 if self._check_update_engine_log_for_entry('Reached max attempts ', 126 raise_error=False): 127 logging.debug('Found log entry for failed update.') 128 if self._is_update_engine_idle(): 129 break 130 time.sleep(1) 131 self._get_update_engine_status() 132 if time.time() > timeout: 133 raise error.TestFail('Update did not fail as expected. Timeout' 134 ': %d minutes.' % timeout_minutes) 135 136 137 def _wait_for_update_to_complete(self, finalizing_ok=False): 138 """ 139 Checks if the update has completed. 140 141 @param finalizing_ok: FINALIZING status counts as complete. 142 143 """ 144 statuses = [self._UPDATE_STATUS_UPDATED_NEED_REBOOT] 145 if finalizing_ok: 146 statuses.append(self._UPDATE_ENGINE_FINALIZING) 147 while True: 148 status = self._get_update_engine_status() 149 150 # During reboot, status will be None 151 if status is not None: 152 if self._UPDATE_STATUS_REPORTING_ERROR_EVENT == status[ 153 self._CURRENT_OP]: 154 err_str = self._get_last_error_string() 155 raise error.TestFail('Update status reported error: %s' % 156 err_str) 157 if status[self._CURRENT_OP] == self._UPDATE_STATUS_IDLE: 158 err_str = self._get_last_error_string() 159 raise error.TestFail('Update status was unexpectedly ' 160 'IDLE when we were waiting for the ' 161 'update to complete: %s' % err_str) 162 if any(arg in status[self._CURRENT_OP] for arg in statuses): 163 break 164 time.sleep(1) 165 166 167 def _get_update_engine_status(self, timeout=3600, ignore_status=True): 168 """Returns a dictionary version of update_engine_client --status""" 169 status = self._run('update_engine_client --status', timeout=timeout, 170 ignore_timeout=True, ignore_status=ignore_status) 171 if status is None: 172 return None 173 logging.debug(status) 174 if status.exit_status != 0: 175 return None 176 status_dict = {} 177 for line in status.stdout.splitlines(): 178 entry = line.partition('=') 179 status_dict[entry[0]] = entry[2] 180 return status_dict 181 182 183 def _check_update_engine_log_for_entry(self, entry, raise_error=False, 184 err_str=None, 185 update_engine_log=None): 186 """ 187 Checks for entries in the update_engine log. 188 189 @param entry: The line to search for. 190 @param raise_error: Fails tests if log doesn't contain entry. 191 @param err_str: The error string to raise if we cannot find entry. 192 @param update_engine_log: Update engine log string you want to 193 search. If None, we will read from the 194 current update engine log. 195 196 @return Boolean if the update engine log contains the entry. 197 198 """ 199 if update_engine_log: 200 result = self._run('echo "%s" | grep "%s"' % (update_engine_log, 201 entry), 202 ignore_status=True) 203 else: 204 result = self._run('cat %s | grep "%s"' % ( 205 self._UPDATE_ENGINE_LOG, entry), ignore_status=True) 206 207 if result.exit_status != 0: 208 if raise_error: 209 error_str = 'Did not find expected string in update_engine ' \ 210 'log: %s' % entry 211 logging.debug(error_str) 212 raise error.TestFail(err_str if err_str else error_str) 213 else: 214 return False 215 return True 216 217 218 def _is_update_finished_downloading(self): 219 """Checks if the update has moved to the final stages.""" 220 s = self._get_update_engine_status() 221 return s[self._CURRENT_OP] in [self._UPDATE_ENGINE_FINALIZING, 222 self._UPDATE_STATUS_UPDATED_NEED_REBOOT] 223 224 225 def _is_update_engine_idle(self): 226 """Checks if the update engine is idle.""" 227 status = self._get_update_engine_status() 228 return status[self._CURRENT_OP] == self._UPDATE_STATUS_IDLE 229 230 231 def _update_continued_where_it_left_off(self, progress): 232 """ 233 Checks that the update did not restart after an interruption. 234 235 @param progress: The progress the last time we checked. 236 237 @returns True if update continued. False if update restarted. 238 239 """ 240 completed = self._get_update_progress() 241 logging.info('New value: %f, old value: %f', completed, progress) 242 return completed >= progress 243 244 245 def _check_for_update(self, server='http://127.0.0.1', port=8082, 246 interactive=True, ignore_status=False, 247 wait_for_completion=False): 248 """ 249 Starts a background update check. 250 251 @param server: The omaha server to call in the update url. 252 @param port: The omaha port to call in the update url. 253 @param interactive: True if we are doing an interactive update. 254 @param ignore_status: True if we should ignore exceptions thrown. 255 @param wait_for_completion: True for --update, False for 256 --check_for_update. 257 """ 258 update = 'update' if wait_for_completion else 'check_for_update' 259 cmd = 'update_engine_client --%s --omaha_url=%s:%d/update ' % (update, 260 server, 261 port) 262 263 if not interactive: 264 cmd += ' --interactive=false' 265 self._run(cmd, ignore_status=ignore_status) 266 267 268 def _save_extra_update_engine_logs(self, number_of_logs=2): 269 """ 270 Get the last X number of update_engine logs on the DUT. 271 272 @param number_of_logs: The number of logs to save. 273 274 """ 275 files = self._run('ls -t -1 %s' % 276 self._UPDATE_ENGINE_LOG_DIR).stdout.splitlines() 277 278 for i in range(number_of_logs if number_of_logs <= len(files) else 279 len(files)): 280 file = os.path.join(self._UPDATE_ENGINE_LOG_DIR, files[i]) 281 self._get_file(file, self.resultsdir) 282 283 284 def _get_second_last_update_engine_log(self): 285 """ 286 Gets second last update engine log text. 287 288 This is useful for getting the last update engine log before a reboot. 289 290 """ 291 files = self._run('ls -t -1 %s' % 292 self._UPDATE_ENGINE_LOG_DIR).stdout.splitlines() 293 return self._run('cat %s%s' % (self._UPDATE_ENGINE_LOG_DIR, 294 files[1])).stdout 295 296 297 def _create_custom_lsb_release(self, update_url, build='0.0.0.0'): 298 """ 299 Create a custom lsb-release file. 300 301 In order to tell OOBE to ping a different update server than the 302 default we need to create our own lsb-release. We will include a 303 deserver update URL. 304 305 @param update_url: String of url to use for update check. 306 @param build: String of the build number to use. Represents the 307 Chrome OS build this device thinks it is on. 308 309 """ 310 self._run('mkdir %s' % os.path.dirname(self._CUSTOM_LSB_RELEASE), 311 ignore_status=True) 312 self._run('touch %s' % self._CUSTOM_LSB_RELEASE) 313 self._run('echo CHROMEOS_RELEASE_VERSION=%s > %s' % 314 (build, self._CUSTOM_LSB_RELEASE)) 315 self._run('echo CHROMEOS_AUSERVER=%s >> %s' % 316 (update_url, self._CUSTOM_LSB_RELEASE)) 317 318 319 def _clear_custom_lsb_release(self): 320 """ 321 Delete the custom release file, if any. 322 323 Intended to clear work done by _create_custom_lsb_release(). 324 325 """ 326 self._run('rm %s' % self._CUSTOM_LSB_RELEASE, ignore_status=True) 327 328 329 def _get_update_requests(self): 330 """ 331 Get the contents of all the update requests from the most recent log. 332 333 @returns: a sequential list of <request> xml blocks or None if none. 334 335 """ 336 update_log = '' 337 with open(self._UPDATE_ENGINE_LOG) as fh: 338 update_log = fh.read() 339 340 # Matches <request ... /request>. The match can be on multiple 341 # lines and the search is not greedy so it only matches one block. 342 return re.findall(r'<request.*?/request>', update_log, re.DOTALL) 343 344 345 def _get_time_of_last_update_request(self): 346 """ 347 Get the time of the last update request from most recent logfile. 348 349 @returns: seconds since epoch of when last update request happened 350 (second accuracy), or None if no such timestamp exists. 351 352 """ 353 update_log = '' 354 with open(self._UPDATE_ENGINE_LOG) as fh: 355 update_log = fh.read() 356 357 # Matches any single line with "MMDD/HHMMSS ... Request ... xml", e.g. 358 # "[0723/133526:INFO:omaha_request_action.cc(794)] Request: <?xml". 359 result = re.findall(r'([0-9]{4}/[0-9]{6}).*Request.*xml', update_log) 360 if not result: 361 return None 362 363 LOG_TIMESTAMP_FORMAT = '%m%d/%H%M%S' 364 match = result[-1] 365 366 # The log does not include the year, so set it as this year. 367 # This assumption could cause incorrect behavior, but is unlikely to. 368 current_year = datetime.datetime.now().year 369 log_datetime = datetime.datetime.strptime(match, LOG_TIMESTAMP_FORMAT) 370 log_datetime = log_datetime.replace(year=current_year) 371 372 return time.mktime(log_datetime.timetuple()) 373 374 375 def _take_screenshot(self, filename): 376 """ 377 Take a screenshot and save in resultsdir. 378 379 @param filename: The name of the file to save 380 381 """ 382 try: 383 file_location = os.path.join('/tmp', filename) 384 self._host.run('screenshot %s' % file_location) 385 self._host.get_file(file_location, self.resultsdir) 386 except error.AutoservRunError: 387 logging.exception('Failed to take screenshot.') 388 389 390 def _get_last_error_string(self): 391 """ 392 Gets the last error message in the update engine log. 393 394 @returns: The error message. 395 396 """ 397 err_str = 'Updating payload state for error code: ' 398 log = self._run('cat %s' % self._UPDATE_ENGINE_LOG).stdout.splitlines() 399 targets = [line for line in log if err_str in line] 400 logging.debug('Error lines found: %s', targets) 401 if not targets: 402 return None 403 else: 404 return targets[-1].rpartition(err_str)[2] 405 406