1# Lint as: python2, python3 2# Copyright 2018 The Chromium OS Authors. All rights reserved. 3# Use of this source code is governed by a BSD-style license that can be 4# found in the LICENSE file. 5 6from __future__ import absolute_import 7from __future__ import division 8from __future__ import print_function 9 10from ctypes import c_size_t 11import datetime 12import json 13import logging 14import os 15import re 16import shutil 17import time 18import six 19from six.moves import range 20import six.moves.urllib_parse as urlparse 21 22from autotest_lib.client.common_lib import error 23from autotest_lib.client.common_lib import utils 24from autotest_lib.client.common_lib.cros import kernel_utils 25from autotest_lib.client.cros.update_engine import nebraska_wrapper 26from autotest_lib.client.cros.update_engine import update_engine_event 27 28_DEFAULT_RUN = utils.run 29_DEFAULT_COPY = shutil.copy 30 31class UpdateEngineUtil(object): 32 """ 33 Utility code shared between client and server update_engine autotests. 34 35 All update_engine autotests inherit from either the client or server 36 version of update_engine_test: 37 client/cros/update_engine/update_engine_test.py 38 server/cros/update_engine/update_engine_test.py 39 40 These update_engine_test classes inherit from test and update_engine_util. 41 For update_engine_util to work seamlessly, we need the client and server 42 update_engine_tests to define _run() and _get_file() functions: 43 server side: host.run and host.get_file 44 client side: utils.run and shutil.copy 45 46 """ 47 48 # Update engine status lines. 49 _PROGRESS = 'PROGRESS' 50 _CURRENT_OP = 'CURRENT_OP' 51 52 # Source version when we force an update. 53 _FORCED_UPDATE = 'ForcedUpdate' 54 55 # update_engine_client command 56 _UPDATE_ENGINE_CLIENT_CMD = 'update_engine_client' 57 58 # Update engine statuses. 59 _UPDATE_STATUS_IDLE = 'UPDATE_STATUS_IDLE' 60 _UPDATE_STATUS_CHECKING_FOR_UPDATE = 'UPDATE_STATUS_CHECKING_FOR_UPDATE' 61 _UPDATE_STATUS_UPDATE_AVAILABLE = 'UPDATE_STATUS_UPDATE_AVAILABLE' 62 _UPDATE_STATUS_DOWNLOADING = 'UPDATE_STATUS_DOWNLOADING' 63 _UPDATE_STATUS_FINALIZING = 'UPDATE_STATUS_FINALIZING' 64 _UPDATE_STATUS_UPDATED_NEED_REBOOT = 'UPDATE_STATUS_UPDATED_NEED_REBOOT' 65 _UPDATE_STATUS_REPORTING_ERROR_EVENT = 'UPDATE_STATUS_REPORTING_ERROR_EVENT' 66 67 # Files used by the tests. 68 _UPDATE_ENGINE_LOG = '/var/log/update_engine.log' 69 _UPDATE_ENGINE_LOG_DIR = '/var/log/update_engine/' 70 _CUSTOM_LSB_RELEASE = '/mnt/stateful_partition/etc/lsb-release' 71 _UPDATE_ENGINE_PREFS_DIR = '/var/lib/update_engine/prefs/' 72 _STATEFUL_MOUNT_DIR = '/mnt/stateful_partition/' 73 74 # Update engine prefs 75 _UPDATE_CHECK_RESPONSE_HASH = 'update-check-response-hash' 76 77 # Interrupt types supported in AU tests. 78 _REBOOT_INTERRUPT = 'reboot' 79 _SUSPEND_INTERRUPT = 'suspend' 80 _NETWORK_INTERRUPT = 'network' 81 _SUPPORTED_INTERRUPTS = [_REBOOT_INTERRUPT, _SUSPEND_INTERRUPT, 82 _NETWORK_INTERRUPT] 83 84 # Public key used to force update_engine to verify omaha response data on 85 # test images. 86 _IMAGE_PUBLIC_KEY = 'LS0tLS1CRUdJTiBQVUJMSUMgS0VZLS0tLS0KTUlJQklqQU5CZ2txaGtpRzl3MEJBUUVGQUFPQ0FROEFNSUlCQ2dLQ0FRRUFxZE03Z25kNDNjV2ZRenlydDE2UQpESEUrVDB5eGcxOE9aTys5c2M4aldwakMxekZ0b01Gb2tFU2l1OVRMVXArS1VDMjc0ZitEeElnQWZTQ082VTVECkpGUlBYVXp2ZTF2YVhZZnFsalVCeGMrSlljR2RkNlBDVWw0QXA5ZjAyRGhrckduZi9ya0hPQ0VoRk5wbTUzZG8Kdlo5QTZRNUtCZmNnMUhlUTA4OG9wVmNlUUd0VW1MK2JPTnE1dEx2TkZMVVUwUnUwQW00QURKOFhtdzRycHZxdgptWEphRm1WdWYvR3g3K1RPbmFKdlpUZU9POUFKSzZxNlY4RTcrWlppTUljNUY0RU9zNUFYL2xaZk5PM1JWZ0cyCk83RGh6emErbk96SjNaSkdLNVI0V3daZHVobjlRUllvZ1lQQjBjNjI4NzhxWHBmMkJuM05wVVBpOENmL1JMTU0KbVFJREFRQUIKLS0tLS1FTkQgUFVCTElDIEtFWS0tLS0tCg==' 87 88 # Screenshot names used by interrupt tests 89 _BEFORE_INTERRUPT_FILENAME = 'before_interrupt.png' 90 _AFTER_INTERRUPT_FILENAME = 'after_interrupt.png' 91 92 # Test name 93 _CLIENT_TEST = 'autoupdate_CannedOmahaUpdate' 94 95 # Feature name 96 _REPEATED_UPDATES_FEATURE = 'feature-repeated-updates' 97 98 # Credentials to use for the fake login in login tests. 99 _LOGIN_TEST_USERNAME = 'autotest' 100 _LOGIN_TEST_PASSWORD = 'password' 101 102 def __init__(self, run_func=_DEFAULT_RUN, get_file=_DEFAULT_COPY): 103 """ 104 Initialize this class with _run() and _get_file() functions. 105 106 @param run_func: the function to use to run commands on the client. 107 Defaults for use by client tests, but can be 108 overwritten to run remotely from a server test. 109 @param get_file: the function to use when copying a file. Defaults 110 for use by client tests. Called with 111 (file, destination) syntax. 112 113 """ 114 self._set_util_functions(run_func, get_file) 115 116 117 def _set_util_functions(self, run_func=_DEFAULT_RUN, 118 get_file=_DEFAULT_COPY): 119 """See __init__().""" 120 self._run = run_func 121 self._get_file = get_file 122 123 124 def _wait_for_progress(self, progress): 125 """ 126 Waits until we reach the percentage passed as the input. 127 128 @param progress: The progress [0.0 .. 1.0] we want to wait for. 129 """ 130 while True: 131 completed = self._get_update_progress() 132 logging.debug('Checking if %s is greater than %s', completed, 133 progress) 134 if completed >= progress: 135 break 136 time.sleep(1) 137 138 139 def _is_update_started(self): 140 """Checks if the update has started.""" 141 status = self._get_update_engine_status() 142 if status is None: 143 return False 144 return status[self._CURRENT_OP] in ( 145 self._UPDATE_STATUS_DOWNLOADING, self._UPDATE_STATUS_FINALIZING) 146 147 148 def _has_progress_stopped(self): 149 """Checks that the update_engine progress has stopped moving.""" 150 before = self._get_update_engine_status()[self._PROGRESS] 151 for i in range(0, 10): 152 if before != self._get_update_engine_status()[self._PROGRESS]: 153 return False 154 time.sleep(1) 155 return True 156 157 158 def _get_update_progress(self): 159 """Returns the current payload downloaded progress.""" 160 while True: 161 status = self._get_update_engine_status() 162 if not status: 163 continue 164 if self._is_update_engine_idle(status): 165 err_str = self._get_last_error_string() 166 raise error.TestFail('Update status was idle while trying to ' 167 'get download status. Last error: %s' % 168 err_str) 169 if self._is_update_engine_reporting_error(status): 170 err_str = self._get_last_error_string() 171 raise error.TestFail('Update status reported error: %s' % 172 err_str) 173 # When the update has moved to the final stages, update engine 174 # displays progress as 0.0 but for our needs we will return 1.0 175 if self._is_update_finished_downloading(status): 176 return 1.0 177 # If we call this right after reboot it may not be downloading yet. 178 if status[self._CURRENT_OP] != self._UPDATE_STATUS_DOWNLOADING: 179 time.sleep(1) 180 continue 181 return float(status[self._PROGRESS]) 182 183 184 def _wait_for_update_to_fail(self): 185 """Waits for the update to retry until failure.""" 186 timeout_minutes = 20 187 timeout = time.time() + 60 * timeout_minutes 188 while True: 189 if self._check_update_engine_log_for_entry('Reached max attempts ', 190 raise_error=False): 191 logging.debug('Found log entry for failed update.') 192 if self._is_update_engine_idle(): 193 break 194 time.sleep(1) 195 self._get_update_engine_status() 196 if time.time() > timeout: 197 raise error.TestFail('Update did not fail as expected. Timeout' 198 ': %d minutes.' % timeout_minutes) 199 200 201 def _wait_for_update_to_complete(self, check_kernel_after_update=True): 202 """ 203 Wait for update status to reach NEED_REBOOT. 204 205 @param check_kernel_after_update: True to also check kernel state after 206 the update. 207 208 """ 209 self._wait_for_update_status(self._UPDATE_STATUS_UPDATED_NEED_REBOOT) 210 if check_kernel_after_update: 211 kernel_utils.verify_kernel_state_after_update( 212 self._host if hasattr(self, '_host') else None) 213 214 215 def _wait_for_update_to_idle(self, 216 check_kernel_after_update=False, 217 inactive_kernel=False): 218 """ 219 Wait for update status to reach IDLE. 220 221 @param check_kernel_after_update: True to also verify kernel state after 222 the update is the expected kernel. 223 @param inactive_kernel: True to indicate the expected kernel is the 224 inactive kernel. 225 226 """ 227 while True: 228 status = self._get_update_engine_status() 229 if self._is_update_engine_idle(status): 230 break 231 time.sleep(1) 232 if check_kernel_after_update: 233 kernel_utils.verify_kernel_state_after_update( 234 self._host if hasattr(self, '_host') else None, 235 inactive_kernel) 236 237 def _wait_for_update_status(self, status_to_wait_for): 238 """ 239 Wait for the update to reach a certain status. 240 241 @param status_to_wait_for: a string of the update status to wait for. 242 243 """ 244 while True: 245 status = self._get_update_engine_status() 246 247 # During reboot, status will be None 248 if status is not None: 249 if self._is_update_engine_reporting_error(status): 250 err_str = self._get_last_error_string() 251 raise error.TestFail('Update status reported error: %s' % 252 err_str) 253 if self._is_update_engine_idle(status): 254 err_str = self._get_last_error_string() 255 raise error.TestFail('Update status was unexpectedly ' 256 'IDLE when we were waiting for the ' 257 'update to complete: %s' % err_str) 258 if status[self._CURRENT_OP] == status_to_wait_for: 259 break 260 time.sleep(1) 261 262 263 def _get_update_engine_status(self, timeout=3600, ignore_timeout=True): 264 """ 265 Gets a dictionary version of update_engine_client --status. 266 267 @param timeout: How long to wait for the status to return. 268 @param ignore_timeout: True to throw an exception if timeout occurs. 269 270 @return Dictionary of values within update_engine_client --status. 271 @raise: error.AutoservError if command times out 272 273 """ 274 status = self._run([self._UPDATE_ENGINE_CLIENT_CMD, '--status'], 275 timeout=timeout, ignore_status=True, 276 ignore_timeout=ignore_timeout) 277 278 if status is None: 279 return None 280 logging.info(status) 281 if status.exit_status != 0: 282 return None 283 status_dict = {} 284 for line in status.stdout.splitlines(): 285 entry = line.partition('=') 286 status_dict[entry[0]] = entry[2] 287 return status_dict 288 289 290 def _check_update_engine_log_for_entry(self, 291 entry, 292 raise_error=False, 293 err_str=None, 294 min_count=1, 295 update_engine_log=None): 296 """ 297 Checks for entries in the update_engine log. 298 299 @param entry: String or tuple of strings to search for. 300 @param raise_error: Fails tests if log doesn't contain entry. 301 @param err_str: The error string to raise if we cannot find entry. 302 @param min_count: The minimum number of times each item should be 303 found in the log. Default one. 304 @param update_engine_log: Update engine log string you want to 305 search. If None, we will read from the 306 current update engine log. 307 308 @return Boolean if the update engine log contains the entry. 309 310 """ 311 if isinstance(entry, str): 312 # Create a tuple of strings so we can iterate over it. 313 entry = (entry,) 314 315 if not update_engine_log: 316 update_engine_log = self._get_update_engine_log() 317 318 if all(update_engine_log.count(msg) >= min_count for msg in entry): 319 return True 320 321 if not raise_error: 322 return False 323 324 error_str = ('Did not find expected string(s) in update_engine log: ' 325 '%s' % entry) 326 logging.debug(error_str) 327 raise error.TestFail(err_str if err_str else error_str) 328 329 330 def _set_feature(self, feature_name, enable=True): 331 """ 332 Enables or disables feature from update engine client. 333 @param feature_name: Name of the feature to enable or disable 334 @param enable: Enables feature if true, disables if false. 335 Default True. 336 """ 337 if not enable: 338 feature_request = '--disable_feature=' + feature_name 339 else: 340 feature_request = '--enable_feature=' + feature_name 341 self._run([self._UPDATE_ENGINE_CLIENT_CMD, feature_request]) 342 343 344 def _is_update_finished_downloading(self, status=None): 345 """ 346 Checks if the update has moved to the final stages. 347 348 @param status: Output of _get_update_engine_status(). If None that 349 function will be called here first. 350 351 """ 352 if status is None: 353 status = self._get_update_engine_status() 354 return status[self._CURRENT_OP] in [ 355 self._UPDATE_STATUS_FINALIZING, 356 self._UPDATE_STATUS_UPDATED_NEED_REBOOT] 357 358 359 def _is_update_engine_idle(self, status=None): 360 """ 361 Checks if the update engine is idle. 362 363 @param status: Output of _get_update_engine_status(). If None that 364 function will be called here first. 365 366 """ 367 if status is None: 368 status = self._get_update_engine_status() 369 return status[self._CURRENT_OP] == self._UPDATE_STATUS_IDLE 370 371 372 def _is_checking_for_update(self, status=None): 373 """ 374 Checks if the update status is still checking for an update. 375 376 @param status: Output of _get_update_engine_status(). If None that 377 function will be called here first. 378 379 """ 380 if status is None: 381 status = self._get_update_engine_status() 382 return status[self._CURRENT_OP] in ( 383 self._UPDATE_STATUS_CHECKING_FOR_UPDATE, 384 self._UPDATE_STATUS_UPDATE_AVAILABLE) 385 386 387 def _is_update_engine_reporting_error(self, status=None): 388 """ 389 Checks if the update engine status reported an error. 390 391 @param status: Output of _get_update_engine_status(). If None that 392 function will be called here first. 393 394 """ 395 if status is None: 396 status = self._get_update_engine_status() 397 return (status[self._CURRENT_OP] == 398 self._UPDATE_STATUS_REPORTING_ERROR_EVENT) 399 400 401 def _update_continued_where_it_left_off(self, progress, 402 reboot_interrupt=False): 403 """ 404 Checks that the update did not restart after an interruption. 405 406 When testing a reboot interrupt we can do additional checks on the 407 logs before and after reboot to see if the update resumed. 408 409 @param progress: The progress the last time we checked. 410 @param reboot_interrupt: True if we are doing a reboot interrupt test. 411 412 @returns True if update continued. False if update restarted. 413 414 """ 415 completed = self._get_update_progress() 416 logging.info('New value: %f, old value: %f', completed, progress) 417 if completed >= progress: 418 return True 419 420 # Sometimes update_engine will continue an update but the first reported 421 # progress won't be correct. So check the logs for resume info. 422 if not reboot_interrupt or not self._check_update_engine_log_for_entry( 423 'Resuming an update that was previously started'): 424 return False 425 426 # Find the reported Completed and Resumed progress. 427 pattern = ('(.*)/(.*) operations \((.*)%\), (.*)/(.*) bytes downloaded' 428 ' \((.*)%\), overall progress (.*)%') 429 before_pattern = 'Completed %s' % pattern 430 before_log = self._get_update_engine_log(r_index=1) 431 before_match = re.findall(before_pattern, before_log)[-1] 432 after_pattern = 'Resuming after %s' % pattern 433 after_log = self._get_update_engine_log(r_index=0) 434 after_match = re.findall(after_pattern, after_log)[0] 435 logging.debug('Progress before interrupt: %s', before_match) 436 logging.debug('Progress after interrupt: %s', after_match) 437 438 # Check the Resuming progress is greater than Completed progress. 439 for i in range(0, len(before_match)): 440 logging.debug('Comparing %d and %d', int(before_match[i]), 441 int(after_match[i])) 442 if int(before_match[i]) > int(after_match[i]): 443 return False 444 return True 445 446 447 def _append_query_to_url(self, url, query_dict): 448 """ 449 Appends the dictionary kwargs to the URL url as query string. 450 451 This function will replace the already existing query strings in url 452 with the ones in the input dictionary. I also removes keys that have 453 a None value. 454 455 @param url: The given input URL. 456 @param query_dicl: A dictionary of key/values to be converted to query 457 string. 458 @return: The same input URL url but with new query string items added. 459 460 """ 461 # TODO(ahassani): This doesn't work (or maybe should not) for queries 462 # with multiple values for a specific key. 463 parsed_url = list(urlparse.urlsplit(url)) 464 parsed_query = urlparse.parse_qs(parsed_url[3]) 465 for k, v in query_dict.items(): 466 parsed_query[k] = [v] 467 parsed_url[3] = '&'.join( 468 '%s=%s' % (k, v[0]) for k, v in parsed_query.items() 469 if v[0] is not None) 470 return urlparse.urlunsplit(parsed_url) 471 472 473 def _check_for_update(self, update_url, interactive=True, 474 wait_for_completion=False, 475 check_kernel_after_update=True, **kwargs): 476 """ 477 Starts a background update check. 478 479 @param update_url: The URL to get an update from. 480 @param interactive: True if we are doing an interactive update. 481 @param wait_for_completion: True for --update, False for 482 --check_for_update. 483 @param check_kernel_after_update: True to check kernel state after a 484 successful update. False to skip. wait_for_completion must also 485 be True. 486 @param kwargs: The dictionary to be converted to a query string and 487 appended to the end of the update URL. e.g: 488 {'critical_update': True, 'foo': 'bar'} -> 489 'http:/127.0.0.1:8080/update?critical_update=True&foo=bar' Look 490 at nebraska.py or devserver.py for the list of accepted 491 values. If there was already query string in update_url, it will 492 append the new values and override the old ones. 493 494 """ 495 update_url = self._append_query_to_url(update_url, kwargs) 496 cmd = [self._UPDATE_ENGINE_CLIENT_CMD, 497 '--update' if wait_for_completion else '--check_for_update', 498 '--omaha_url=%s' % update_url] 499 500 if not interactive: 501 cmd.append('--interactive=false') 502 self._run(cmd, ignore_status=False) 503 if wait_for_completion and check_kernel_after_update: 504 kernel_utils.verify_kernel_state_after_update( 505 self._host if hasattr(self, '_host') else None) 506 507 508 def _rollback(self, powerwash=False): 509 """ 510 Perform a rollback of rootfs. 511 512 @param powerwash: True to powerwash along with the rollback. 513 514 """ 515 cmd = [self._UPDATE_ENGINE_CLIENT_CMD, '--rollback', '--follow'] 516 if not powerwash: 517 cmd.append('--nopowerwash') 518 logging.info('Performing rollback with cmd: %s.', cmd) 519 self._run(cmd) 520 kernel_utils.verify_kernel_state_after_update(self._host) 521 522 523 def _restart_update_engine(self, ignore_status=False): 524 """ 525 Restarts update-engine. 526 527 @param ignore_status: True to not raise exception on command failure. 528 529 """ 530 self._run(['restart', 'update-engine'], ignore_status=ignore_status) 531 532 533 def _save_extra_update_engine_logs(self, number_of_logs): 534 """ 535 Get the last X number of update_engine logs on the DUT. 536 537 @param number_of_logs: The number of logs to save. 538 539 """ 540 files = self._get_update_engine_logs() 541 542 for i in range(number_of_logs if number_of_logs <= len(files) else 543 len(files)): 544 file = os.path.join(self._UPDATE_ENGINE_LOG_DIR, files[i]) 545 self._get_file(file, self.resultsdir) 546 547 548 def _get_update_engine_logs(self, timeout=3600, ignore_timeout=True): 549 """ 550 Helper function to return the list of files in /var/log/update_engine/. 551 552 @param timeout: How many seconds to wait for command to complete. 553 @param ignore_timeout: True if we should not throw an error on timeout. 554 555 """ 556 cmd = ['ls', '-t', '-1', self._UPDATE_ENGINE_LOG_DIR] 557 return self._run(cmd, timeout=timeout, 558 ignore_timeout=ignore_timeout).stdout.splitlines() 559 560 561 def _get_update_engine_log(self, r_index=0, timeout=3600, 562 ignore_timeout=True): 563 """ 564 Returns the last r_index'th update_engine log. 565 566 @param r_index: The index of the last r_index'th update_engine log 567 in order they were created. For example: 568 0 -> last one. 569 1 -> second to last one. 570 @param timeout: How many seconds to wait for command to complete. 571 @param ignore_timeout: True if we should not throw an error on timeout. 572 573 """ 574 files = self._get_update_engine_logs() 575 log_file = os.path.join(self._UPDATE_ENGINE_LOG_DIR, files[r_index]) 576 return self._run(['cat', log_file]).stdout 577 578 579 def _create_custom_lsb_release(self, update_url, build='0.0.0.0', **kwargs): 580 """ 581 Create a custom lsb-release file. 582 583 In order to tell OOBE to ping a different update server than the 584 default we need to create our own lsb-release. We will include a 585 deserver update URL. 586 587 @param update_url: String of url to use for update check. 588 @param build: String of the build number to use. Represents the 589 ChromeOS build this device thinks it is on. 590 @param kwargs: A dictionary of key/values to be made into a query string 591 and appended to the update_url 592 593 """ 594 update_url = self._append_query_to_url(update_url, kwargs) 595 release_version = 'CHROMEOS_RELEASE_VERSION=%s' % build 596 auserver = 'CHROMEOS_AUSERVER=%s' % update_url 597 598 self._run(['mkdir', os.path.dirname(self._CUSTOM_LSB_RELEASE)], 599 ignore_status=True) 600 self._run(['touch', self._CUSTOM_LSB_RELEASE]) 601 self._run(['echo', release_version, '>', self._CUSTOM_LSB_RELEASE]) 602 self._run(['echo', auserver, '>>', self._CUSTOM_LSB_RELEASE]) 603 604 # Confirm the custom lsb-release file was created successfully. 605 def custom_lsb_created(): 606 """ 607 Checks if the custom lsb-release file exists and has the correct 608 contents. 609 610 @returns: True if the file exists with the expected contents 611 False otherwise 612 """ 613 contents = self._run(['cat', self._CUSTOM_LSB_RELEASE]).stdout 614 return auserver in contents and release_version in contents 615 616 utils.poll_for_condition(condition=custom_lsb_created) 617 618 619 def _clear_custom_lsb_release(self): 620 """ 621 Delete the custom release file, if any. 622 623 Intended to clear work done by _create_custom_lsb_release(). 624 625 """ 626 self._run(['rm', self._CUSTOM_LSB_RELEASE], ignore_status=True) 627 628 629 def _remove_update_engine_pref(self, pref, is_dir=False): 630 """ 631 Delete an update_engine pref file or directory. 632 633 @param pref: The pref file to delete 634 @param is_dir: True for removing a whole pref subdirectory. 635 636 """ 637 pref_file = os.path.join(self._UPDATE_ENGINE_PREFS_DIR, pref) 638 self._run(['rm', '-r' if is_dir else '', pref_file], 639 ignore_status=True) 640 641 def _create_update_engine_pref(self, pref_name, pref_val="", sub_dir=None): 642 """ 643 Create an update_engine pref file. 644 645 @param pref_name: The name of pref file to create. 646 @param pref_val: The content string in pref file. 647 @param sub_dir: The sub directory for the pref. 648 649 """ 650 pref_dir = self._UPDATE_ENGINE_PREFS_DIR 651 if sub_dir: 652 pref_dir = os.path.join(pref_dir, sub_dir) 653 self._run(['mkdir', '-p', pref_dir], ignore_status=True) 654 655 pref_file = os.path.join(pref_dir, pref_name) 656 self._run(['echo', '-n', pref_val, '>', pref_file]) 657 658 def _get_update_requests(self): 659 """ 660 Get the contents of all the update requests from the most recent log. 661 662 @returns: a sequential list of <request> xml blocks or None if none. 663 664 """ 665 update_log = self._get_update_engine_log() 666 667 # Matches <request ... /request>. The match can be on multiple 668 # lines and the search is not greedy so it only matches one block. 669 return re.findall(r'<request.*?/request>', update_log, re.DOTALL) 670 671 672 def _get_time_of_last_update_request(self): 673 """ 674 Get the time of the last update request from most recent logfile. 675 676 @returns: seconds since epoch of when last update request happened 677 (second accuracy), or None if no such timestamp exists. 678 679 """ 680 update_log = self._get_update_engine_log() 681 682 # Matches any line with "YYYY-MM-DDTHH:MM:SS ... Request ... xml", 683 # e.g. 684 # "2021-01-28T10:14:33.998217Z INFO update_engine: \ 685 # [omaha_request_action.cc(794)] Request: <?xml" 686 pattern = r'(\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}).* Request:.*xml' 687 LOG_TIMESTAMP_FORMAT = '%Y-%m-%dT%H:%M:%S' 688 689 result = re.findall(pattern, update_log) 690 691 if result: 692 match = result[-1] 693 log_datetime = datetime.datetime.strptime(match, 694 LOG_TIMESTAMP_FORMAT) 695 epoch = datetime.datetime(1970, 1, 1) 696 697 # Since log_datetime is in UTC, simply take the diff from epoch. 698 return (log_datetime - epoch).total_seconds() 699 else: 700 # If no match for new timestamp, try old timestamp format. 701 # "[0723/133526:INFO:omaha_request_action.cc(794)] Request: <?xml". 702 pattern_old = r'([0-9]{4}/[0-9]{6}).*Request.*xml' 703 LOG_TIMESTAMP_FORMAT_OLD = '%m%d/%H%M%S' 704 705 result = re.findall(pattern_old, update_log) 706 if not result: 707 return None 708 709 match = result[-1] 710 711 # The old format does not include the year, so set it as this year. 712 # This could cause incorrect behavior, but is unlikely to. 713 current_year = datetime.datetime.now().year 714 log_datetime = datetime.datetime.strptime( 715 match, LOG_TIMESTAMP_FORMAT_OLD) 716 log_datetime = log_datetime.replace(year=current_year) 717 718 return time.mktime(log_datetime.timetuple()) 719 720 721 def _take_screenshot(self, filename): 722 """ 723 Take a screenshot and save in resultsdir. 724 725 @param filename: The name of the file to save 726 727 """ 728 try: 729 file_location = os.path.join('/tmp', filename) 730 self._run(['screenshot', file_location]) 731 self._get_file(file_location, self.resultsdir) 732 except (error.AutoservRunError, error.CmdError): 733 logging.exception('Failed to take screenshot.') 734 735 736 def _remove_screenshots(self): 737 """Remove screenshots taken by interrupt tests.""" 738 for file in [self._BEFORE_INTERRUPT_FILENAME, 739 self._AFTER_INTERRUPT_FILENAME]: 740 file_location = os.path.join(self.resultsdir, file) 741 if os.path.exists(file_location): 742 try: 743 os.remove(file_location) 744 except Exception as e: 745 logging.exception('Failed to remove %s', file_location) 746 747 748 def _get_last_error_string(self): 749 """ 750 Gets the last error message in the update engine log. 751 752 @returns: The error message. 753 754 """ 755 err_str = 'Updating payload state for error code: ' 756 log = self._get_update_engine_log().splitlines() 757 targets = [line for line in log if err_str in line] 758 logging.debug('Error lines found: %s', targets) 759 if not targets: 760 return None 761 else: 762 return targets[-1].rpartition(err_str)[2] 763 764 765 def _get_latest_initial_request(self): 766 """ 767 Return the most recent initial update request. 768 769 AU requests occur in a chain of messages back and forth, e.g. the 770 initial request for an update -> the reply with the update -> the 771 report that install has started -> report that install has finished, 772 etc. This function finds the first request in the latest such chain. 773 774 This message has no eventtype listed, or is rebooted_after_update 775 type (as an artifact from a previous update since this one). 776 Subsequent messages in the chain have different eventtype values. 777 778 @returns: string of the entire update request or None. 779 780 """ 781 requests = self._get_update_requests() 782 if not requests: 783 return None 784 785 MATCH_STR = r'eventtype="(.*?)"' 786 for i in range(len(requests) - 1, -1, -1): 787 search = re.search(MATCH_STR, requests[i]) 788 if (not search or 789 (search.group(1) == 790 str(update_engine_event.EVENT_TYPE_REBOOTED_AFTER_UPDATE))): 791 return requests[i] 792 793 return None 794 795 def _edit_nebraska_startup_config(self, **kwargs): 796 """ 797 Edits an existing nebraska startup config file. 798 799 @param kwargs: A dictionary of key/values for nebraska config options. 800 See platform/dev/nebraska/nebraska.py for more info. 801 802 """ 803 conf = json.loads( 804 self._run(['cat', nebraska_wrapper.NEBRASKA_CONFIG]).stdout) 805 for k, v in six.iteritems(kwargs): 806 conf[k] = v 807 self._run([ 808 'echo', 809 json.dumps(conf), '>', nebraska_wrapper.NEBRASKA_CONFIG 810 ]) 811 812 def _clear_nebraska_dir(self): 813 """ 814 Clears the nebraska dir on the DUT where the nebraska config and payload 815 metadata files are stored. 816 817 """ 818 self._run(['rm', '-rf', '/usr/local/nebraska']) 819 820 def _get_nebraska_update_url(self): 821 """ 822 Gets the update URL for an active nebraska server. Assumes nebraska is 823 up and running. 824 825 @returns: string of the update URL for the active nebraska. 826 827 """ 828 nebraska_port = self._run(['cat', '/run/nebraska/port']).stdout 829 return 'http://localhost:%s/update' % nebraska_port 830 831 def _get_exclusion_name(self, payload_url): 832 """ 833 Get the exclusion name of a payload url by calculating its hash in the 834 same way of base::StringPieceHash in libchrome. 835 836 @param payload_url: The payload url to be excluded. 837 838 @returns: The payload URL hash string as the exclusion name. 839 840 """ 841 result = c_size_t(0) 842 for c in payload_url: 843 result = c_size_t((result.value * 131) + ord(c)) 844 return str(result.value) 845