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 json 7import logging 8import os 9import re 10import requests 11import shutil 12import time 13 14from autotest_lib.client.common_lib import error 15from autotest_lib.client.common_lib import utils 16from autotest_lib.client.cros.update_engine import update_engine_event 17 18_DEFAULT_RUN = utils.run 19_DEFAULT_COPY = shutil.copy 20 21class UpdateEngineUtil(object): 22 """Utility code shared between client and server update_engine autotests""" 23 24 # Update engine status lines. 25 _LAST_CHECKED_TIME = 'LAST_CHECKED_TIME' 26 _PROGRESS = 'PROGRESS' 27 _CURRENT_OP = 'CURRENT_OP' 28 _NEW_VERSION = 'NEW VERSION' 29 _NEW_SIZE = 'NEW_SIZE' 30 31 # Update engine statuses. 32 _UPDATE_STATUS_IDLE = 'UPDATE_STATUS_IDLE' 33 _UPDATE_ENGINE_DOWNLOADING = 'UPDATE_STATUS_DOWNLOADING' 34 _UPDATE_ENGINE_FINALIZING = 'UPDATE_STATUS_FINALIZING' 35 _UPDATE_STATUS_UPDATED_NEED_REBOOT = 'UPDATE_STATUS_UPDATED_NEED_REBOOT' 36 _UPDATE_STATUS_REPORTING_ERROR_EVENT = 'UPDATE_STATUS_REPORTING_ERROR_EVENT' 37 38 # Files used by the tests. 39 _UPDATE_ENGINE_LOG = '/var/log/update_engine.log' 40 _UPDATE_ENGINE_LOG_DIR = '/var/log/update_engine/' 41 _CUSTOM_LSB_RELEASE = '/mnt/stateful_partition/etc/lsb-release' 42 _UPDATE_ENGINE_PREFS_DIR = '/var/lib/update_engine/prefs/' 43 44 # Public key used to force update_engine to verify omaha response data on 45 # test images. 46 _IMAGE_PUBLIC_KEY = 'LS0tLS1CRUdJTiBQVUJMSUMgS0VZLS0tLS0KTUlJQklqQU5CZ2txaGtpRzl3MEJBUUVGQUFPQ0FROEFNSUlCQ2dLQ0FRRUFxZE03Z25kNDNjV2ZRenlydDE2UQpESEUrVDB5eGcxOE9aTys5c2M4aldwakMxekZ0b01Gb2tFU2l1OVRMVXArS1VDMjc0ZitEeElnQWZTQ082VTVECkpGUlBYVXp2ZTF2YVhZZnFsalVCeGMrSlljR2RkNlBDVWw0QXA5ZjAyRGhrckduZi9ya0hPQ0VoRk5wbTUzZG8Kdlo5QTZRNUtCZmNnMUhlUTA4OG9wVmNlUUd0VW1MK2JPTnE1dEx2TkZMVVUwUnUwQW00QURKOFhtdzRycHZxdgptWEphRm1WdWYvR3g3K1RPbmFKdlpUZU9POUFKSzZxNlY4RTcrWlppTUljNUY0RU9zNUFYL2xaZk5PM1JWZ0cyCk83RGh6emErbk96SjNaSkdLNVI0V3daZHVobjlRUllvZ1lQQjBjNjI4NzhxWHBmMkJuM05wVVBpOENmL1JMTU0KbVFJREFRQUIKLS0tLS1FTkQgUFVCTElDIEtFWS0tLS0tCg==' 47 48 49 def __init__(self, run_func=_DEFAULT_RUN, get_file=_DEFAULT_COPY): 50 """ 51 Initialize this class. 52 53 @param run_func: the function to use to run commands on the client. 54 Defaults for use by client tests, but can be 55 overwritten to run remotely from a server test. 56 @param get_file: the function to use when copying a file. Defaults 57 for use by client tests. Called with 58 (file, destination) syntax. 59 60 """ 61 self._create_update_engine_variables(run_func, get_file) 62 63 64 def _create_update_engine_variables(self, run_func=_DEFAULT_RUN, 65 get_file=_DEFAULT_COPY): 66 """See __init__().""" 67 self._run = run_func 68 self._get_file = get_file 69 70 71 def _wait_for_progress(self, progress): 72 """ 73 Waits until we reach the percentage passed as the input. 74 75 @param progress: The progress [0.0 .. 1.0] we want to wait for. 76 """ 77 while True: 78 completed = self._get_update_progress() 79 logging.debug('Checking if %s is greater than %s', completed, 80 progress) 81 if completed >= progress: 82 break 83 time.sleep(1) 84 85 86 def _is_update_started(self): 87 """Checks if the update has started.""" 88 status = self._get_update_engine_status() 89 if status is None: 90 return False 91 return any(arg == status[self._CURRENT_OP] for arg in 92 [self._UPDATE_ENGINE_DOWNLOADING, self._UPDATE_ENGINE_FINALIZING]) 93 94 95 def _get_update_progress(self): 96 """Returns the current payload downloaded progress.""" 97 while True: 98 status = self._get_update_engine_status() 99 if not status: 100 continue 101 if self._UPDATE_STATUS_IDLE == status[self._CURRENT_OP]: 102 err_str = self._get_last_error_string() 103 raise error.TestFail('Update status was idle while trying to ' 104 'get download status. Last error: %s' % 105 err_str) 106 if self._UPDATE_STATUS_REPORTING_ERROR_EVENT == status[ 107 self._CURRENT_OP]: 108 err_str = self._get_last_error_string() 109 raise error.TestFail('Update status reported error: %s' % 110 err_str) 111 # When the update has moved to the final stages, update engine 112 # displays progress as 0.0 but for our needs we will return 1.0 113 if status[self._CURRENT_OP] in [ 114 self._UPDATE_STATUS_UPDATED_NEED_REBOOT, 115 self._UPDATE_ENGINE_FINALIZING]: 116 return 1.0 117 # If we call this right after reboot it may not be downloading yet. 118 if self._UPDATE_ENGINE_DOWNLOADING != status[self._CURRENT_OP]: 119 time.sleep(1) 120 continue 121 return float(status[self._PROGRESS]) 122 123 124 def _wait_for_update_to_fail(self): 125 """Waits for the update to retry until failure.""" 126 timeout_minutes = 20 127 timeout = time.time() + 60 * timeout_minutes 128 while True: 129 if self._check_update_engine_log_for_entry('Reached max attempts ', 130 raise_error=False): 131 logging.debug('Found log entry for failed update.') 132 if self._is_update_engine_idle(): 133 break 134 time.sleep(1) 135 self._get_update_engine_status() 136 if time.time() > timeout: 137 raise error.TestFail('Update did not fail as expected. Timeout' 138 ': %d minutes.' % timeout_minutes) 139 140 141 def _wait_for_update_to_complete(self, finalizing_ok=False): 142 """ 143 Checks if the update has completed. 144 145 @param finalizing_ok: FINALIZING status counts as complete. 146 147 """ 148 statuses = [self._UPDATE_STATUS_UPDATED_NEED_REBOOT] 149 if finalizing_ok: 150 statuses.append(self._UPDATE_ENGINE_FINALIZING) 151 while True: 152 status = self._get_update_engine_status() 153 154 # During reboot, status will be None 155 if status is not None: 156 if self._UPDATE_STATUS_REPORTING_ERROR_EVENT == status[ 157 self._CURRENT_OP]: 158 err_str = self._get_last_error_string() 159 raise error.TestFail('Update status reported error: %s' % 160 err_str) 161 if status[self._CURRENT_OP] == self._UPDATE_STATUS_IDLE: 162 err_str = self._get_last_error_string() 163 raise error.TestFail('Update status was unexpectedly ' 164 'IDLE when we were waiting for the ' 165 'update to complete: %s' % err_str) 166 if any(arg in status[self._CURRENT_OP] for arg in statuses): 167 break 168 time.sleep(1) 169 170 171 def _get_update_engine_status(self, timeout=3600, ignore_timeout=True): 172 """ 173 Gets a dictionary version of update_engine_client --status. 174 175 @param timeout: How long to wait for the status to return. 176 @param ignore_timeout: True to throw an exception if timeout occurs. 177 178 @return Dictionary of values within update_engine_client --status. 179 @raise: error.AutoservError if command times out 180 181 """ 182 status = self._run('update_engine_client --status', timeout=timeout, 183 ignore_status=True, ignore_timeout=ignore_timeout) 184 185 if status is None: 186 return None 187 logging.info(status) 188 if status.exit_status != 0: 189 return None 190 status_dict = {} 191 for line in status.stdout.splitlines(): 192 entry = line.partition('=') 193 status_dict[entry[0]] = entry[2] 194 return status_dict 195 196 197 def _check_update_engine_log_for_entry(self, entry, raise_error=False, 198 err_str=None, 199 update_engine_log=None): 200 """ 201 Checks for entries in the update_engine log. 202 203 @param entry: The line to search for. 204 @param raise_error: Fails tests if log doesn't contain entry. 205 @param err_str: The error string to raise if we cannot find entry. 206 @param update_engine_log: Update engine log string you want to 207 search. If None, we will read from the 208 current update engine log. 209 210 @return Boolean if the update engine log contains the entry. 211 212 """ 213 if isinstance(entry, str): 214 # Create a tuple of strings so we can itarete over it. 215 entry = (entry,) 216 217 if not update_engine_log: 218 update_engine_log = self._run( 219 'cat %s' % self._UPDATE_ENGINE_LOG).stdout 220 221 if all(msg in update_engine_log for msg in entry): 222 return True 223 224 if not raise_error: 225 return False 226 227 error_str = ('Did not find expected string(s) in update_engine log: ' 228 '%s' % entry) 229 logging.debug(error_str) 230 raise error.TestFail(err_str if err_str else error_str) 231 232 233 def _is_update_finished_downloading(self): 234 """Checks if the update has moved to the final stages.""" 235 s = self._get_update_engine_status() 236 return s[self._CURRENT_OP] in [self._UPDATE_ENGINE_FINALIZING, 237 self._UPDATE_STATUS_UPDATED_NEED_REBOOT] 238 239 240 def _is_update_engine_idle(self): 241 """Checks if the update engine is idle.""" 242 status = self._get_update_engine_status() 243 return status[self._CURRENT_OP] == self._UPDATE_STATUS_IDLE 244 245 246 def _update_continued_where_it_left_off(self, progress): 247 """ 248 Checks that the update did not restart after an interruption. 249 250 @param progress: The progress the last time we checked. 251 252 @returns True if update continued. False if update restarted. 253 254 """ 255 completed = self._get_update_progress() 256 logging.info('New value: %f, old value: %f', completed, progress) 257 return completed >= progress 258 259 260 def _get_payload_properties_file(self, payload_url, target_dir, **kwargs): 261 """ 262 Downloads the payload properties file into a directory. 263 264 @param payload_url: The URL to the update payload file. 265 @param target_dir: The directory to download the file into. 266 @param kwargs: A dictionary of key/values that needs to be overridden on 267 the payload properties file. 268 269 """ 270 payload_props_url = payload_url + '.json' 271 _, _, file_name = payload_props_url.rpartition('/') 272 try: 273 response = json.loads(requests.get(payload_props_url).text) 274 275 # Override existing keys if any. 276 for k, v in kwargs.iteritems(): 277 # Don't set default None values. We don't want to override good 278 # values to None. 279 if v is not None: 280 response[k] = v 281 282 with open(os.path.join(target_dir, file_name), 'w') as fp: 283 json.dump(response, fp) 284 285 except (requests.exceptions.RequestException, 286 IOError, 287 ValueError) as err: 288 raise error.TestError( 289 'Failed to get update payload properties: %s with error: %s' % 290 (payload_props_url, err)) 291 292 293 def _check_for_update(self, server='http://127.0.0.1', port=8082, 294 update_path='update', interactive=True, 295 ignore_status=False, wait_for_completion=False, 296 **kwargs): 297 """ 298 Starts a background update check. 299 300 @param server: The omaha server to call in the update url. 301 @param port: The omaha port to call in the update url. 302 @param update_path: The /update part of the URL. When using a lab 303 devserver, pass update/<board>-release/RXX-X.X.X. 304 @param interactive: True if we are doing an interactive update. 305 @param ignore_status: True if we should ignore exceptions thrown. 306 @param wait_for_completion: True for --update, False for 307 --check_for_update. 308 @param kwargs: The dictionary to be converted to a query string 309 and appended to the end of the update URL. e.g: 310 {'critical_update': True, 'foo': 'bar'} -> 311 'http:/127.0.0.1:8080/update?critical_update=True&foo=bar' 312 Look at nebraska.py or devserver.py for the list of accepted 313 values. 314 """ 315 update = 'update' if wait_for_completion else 'check_for_update' 316 update_path = update_path.lstrip('/') 317 query = '&'.join('%s=%s' % (k, v) for k, v in kwargs.items()) 318 cmd = 'update_engine_client --%s --omaha_url="%s:%d/%s?%s"' % ( 319 update, server, port, update_path, query) 320 321 if not interactive: 322 cmd += ' --interactive=false' 323 self._run(cmd, ignore_status=ignore_status) 324 325 326 def _save_extra_update_engine_logs(self, number_of_logs=2): 327 """ 328 Get the last X number of update_engine logs on the DUT. 329 330 @param number_of_logs: The number of logs to save. 331 332 """ 333 files = self._run('ls -t -1 %s' % 334 self._UPDATE_ENGINE_LOG_DIR).stdout.splitlines() 335 336 for i in range(number_of_logs if number_of_logs <= len(files) else 337 len(files)): 338 file = os.path.join(self._UPDATE_ENGINE_LOG_DIR, files[i]) 339 self._get_file(file, self.resultsdir) 340 341 342 def _get_second_last_update_engine_log(self): 343 """ 344 Gets second last update engine log text. 345 346 This is useful for getting the last update engine log before a reboot. 347 348 """ 349 files = self._run('ls -t -1 %s' % 350 self._UPDATE_ENGINE_LOG_DIR).stdout.splitlines() 351 return self._run('cat %s%s' % (self._UPDATE_ENGINE_LOG_DIR, 352 files[1])).stdout 353 354 355 def _create_custom_lsb_release(self, update_url, build='0.0.0.0', **kwargs): 356 """ 357 Create a custom lsb-release file. 358 359 In order to tell OOBE to ping a different update server than the 360 default we need to create our own lsb-release. We will include a 361 deserver update URL. 362 363 @param update_url: String of url to use for update check. 364 @param build: String of the build number to use. Represents the 365 Chrome OS build this device thinks it is on. 366 @param kwargs: A dictionary of key/values to be made into a query string 367 and appended to the update_url 368 369 """ 370 # TODO(ahassani): This is quite fragile as the given URL can already 371 # have a search query. We need to unpack the URL and update the search 372 # query portion of it with kwargs. 373 update_url = (update_url + '?' + '&'.join('%s=%s' % (k, v) 374 for k, v in kwargs.items())) 375 self._run('mkdir %s' % os.path.dirname(self._CUSTOM_LSB_RELEASE), 376 ignore_status=True) 377 self._run('touch %s' % self._CUSTOM_LSB_RELEASE) 378 self._run('echo CHROMEOS_RELEASE_VERSION=%s > %s' % 379 (build, self._CUSTOM_LSB_RELEASE)) 380 self._run('echo CHROMEOS_AUSERVER=%s >> %s' % 381 (update_url, self._CUSTOM_LSB_RELEASE)) 382 383 384 def _clear_custom_lsb_release(self): 385 """ 386 Delete the custom release file, if any. 387 388 Intended to clear work done by _create_custom_lsb_release(). 389 390 """ 391 self._run('rm %s' % self._CUSTOM_LSB_RELEASE, ignore_status=True) 392 393 394 def _get_update_requests(self): 395 """ 396 Get the contents of all the update requests from the most recent log. 397 398 @returns: a sequential list of <request> xml blocks or None if none. 399 400 """ 401 update_log = self._run('cat %s' % 402 self._UPDATE_ENGINE_LOG).stdout 403 404 # Matches <request ... /request>. The match can be on multiple 405 # lines and the search is not greedy so it only matches one block. 406 return re.findall(r'<request.*?/request>', update_log, re.DOTALL) 407 408 409 def _get_time_of_last_update_request(self): 410 """ 411 Get the time of the last update request from most recent logfile. 412 413 @returns: seconds since epoch of when last update request happened 414 (second accuracy), or None if no such timestamp exists. 415 416 """ 417 update_log = '' 418 with open(self._UPDATE_ENGINE_LOG) as fh: 419 update_log = fh.read() 420 421 # Matches any single line with "MMDD/HHMMSS ... Request ... xml", e.g. 422 # "[0723/133526:INFO:omaha_request_action.cc(794)] Request: <?xml". 423 result = re.findall(r'([0-9]{4}/[0-9]{6}).*Request.*xml', update_log) 424 if not result: 425 return None 426 427 LOG_TIMESTAMP_FORMAT = '%m%d/%H%M%S' 428 match = result[-1] 429 430 # The log does not include the year, so set it as this year. 431 # This assumption could cause incorrect behavior, but is unlikely to. 432 current_year = datetime.datetime.now().year 433 log_datetime = datetime.datetime.strptime(match, LOG_TIMESTAMP_FORMAT) 434 log_datetime = log_datetime.replace(year=current_year) 435 436 return time.mktime(log_datetime.timetuple()) 437 438 439 def _take_screenshot(self, filename): 440 """ 441 Take a screenshot and save in resultsdir. 442 443 @param filename: The name of the file to save 444 445 """ 446 try: 447 file_location = os.path.join('/tmp', filename) 448 self._run('screenshot %s' % file_location) 449 self._get_file(file_location, self.resultsdir) 450 except error.AutoservRunError: 451 logging.exception('Failed to take screenshot.') 452 453 454 def _get_last_error_string(self): 455 """ 456 Gets the last error message in the update engine log. 457 458 @returns: The error message. 459 460 """ 461 err_str = 'Updating payload state for error code: ' 462 log = self._run('cat %s' % self._UPDATE_ENGINE_LOG).stdout.splitlines() 463 targets = [line for line in log if err_str in line] 464 logging.debug('Error lines found: %s', targets) 465 if not targets: 466 return None 467 else: 468 return targets[-1].rpartition(err_str)[2] 469 470 471 def _get_latest_initial_request(self): 472 """ 473 Return the most recent initial update request. 474 475 AU requests occur in a chain of messages back and forth, e.g. the 476 initial request for an update -> the reply with the update -> the 477 report that install has started -> report that install has finished, 478 etc. This function finds the first request in the latest such chain. 479 480 This message has no eventtype listed, or is rebooted_after_update 481 type (as an artifact from a previous update since this one). 482 Subsequent messages in the chain have different eventtype values. 483 484 @returns: string of the entire update request or None. 485 486 """ 487 requests = self._get_update_requests() 488 if not requests: 489 return None 490 491 MATCH_STR = r'eventtype="(.*?)"' 492 for i in xrange(len(requests) - 1, -1, -1): 493 search = re.search(MATCH_STR, requests[i]) 494 if (not search or 495 (search.group(1) == 496 update_engine_event.EVENT_TYPE_REBOOTED_AFTER_UPDATE)): 497 return requests[i] 498 499 return None 500