1# Copyright (c) 2012 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 5from datetime import datetime, timedelta 6import collections 7import json 8import logging 9import os 10import time 11import urlparse 12 13from autotest_lib.client.common_lib import error 14from autotest_lib.client.common_lib.cros import dev_server 15from autotest_lib.server import autotest, test 16from autotest_lib.server.cros.dynamic_suite import tools 17 18 19def snippet(text): 20 """Returns the text with start/end snip markers around it. 21 22 @param text: The snippet text. 23 24 @return The text with start/end snip markers around it. 25 """ 26 snip = '---8<---' * 10 27 start = '-- START -' 28 end = '-- END -' 29 return ('%s%s\n%s\n%s%s' % 30 (start, snip[len(start):], text, end, snip[len(end):])) 31 32UPDATE_ENGINE_PERF_PATH = '/mnt/stateful_partition/unencrypted/preserve' 33UPDATE_ENGINE_PERF_SCRIPT = 'update_engine_performance_monitor.py' 34UPDATE_ENGINE_PERF_RESULTS_FILE = 'perf_data_results.json' 35 36# Update event types. 37EVENT_TYPE_DOWNLOAD_COMPLETE = '1' 38EVENT_TYPE_INSTALL_COMPLETE = '2' 39EVENT_TYPE_UPDATE_COMPLETE = '3' 40EVENT_TYPE_DOWNLOAD_STARTED = '13' 41EVENT_TYPE_DOWNLOAD_FINISHED = '14' 42EVENT_TYPE_REBOOTED_AFTER_UPDATE = '54' 43 44# Update event results. 45EVENT_RESULT_ERROR = '0' 46EVENT_RESULT_SUCCESS = '1' 47EVENT_RESULT_SUCCESS_REBOOT = '2' 48EVENT_RESULT_UPDATE_DEFERRED = '9' 49 50# Omaha event types/results, from update_engine/omaha_request_action.h 51# These are stored in dict form in order to easily print out the keys. 52EVENT_TYPE_DICT = { 53 EVENT_TYPE_DOWNLOAD_COMPLETE: 'download_complete', 54 EVENT_TYPE_INSTALL_COMPLETE: 'install_complete', 55 EVENT_TYPE_UPDATE_COMPLETE: 'update_complete', 56 EVENT_TYPE_DOWNLOAD_STARTED: 'download_started', 57 EVENT_TYPE_DOWNLOAD_FINISHED: 'download_finished', 58 EVENT_TYPE_REBOOTED_AFTER_UPDATE: 'rebooted_after_update' 59} 60 61EVENT_RESULT_DICT = { 62 EVENT_RESULT_ERROR: 'error', 63 EVENT_RESULT_SUCCESS: 'success', 64 EVENT_RESULT_SUCCESS_REBOOT: 'success_reboot', 65 EVENT_RESULT_UPDATE_DEFERRED: 'update_deferred' 66} 67 68 69class ExpectedUpdateEventChainFailed(error.TestFail): 70 """Raised if we fail to receive an expected event in a chain.""" 71 72 73class ExpectedUpdateEvent(object): 74 """Defines an expected event in an update process.""" 75 76 _ATTR_NAME_DICT_MAP = { 77 'event_type': EVENT_TYPE_DICT, 78 'event_result': EVENT_RESULT_DICT, 79 } 80 81 _VALID_TYPES = set(EVENT_TYPE_DICT.keys()) 82 _VALID_RESULTS = set(EVENT_RESULT_DICT.keys()) 83 84 def __init__(self, event_type=None, event_result=None, version=None, 85 previous_version=None, on_error=None): 86 """Initializes an event expectation. 87 88 @param event_type: Expected event type. 89 @param event_result: Expected event result code. 90 @param version: Expected reported image version. 91 @param previous_version: Expected reported previous image version. 92 @param on_error: This is either an object to be returned when a received 93 event mismatches the expectation, or a callable used 94 for generating one. In the latter case, takes as 95 input two attribute dictionaries (expected and actual) 96 and an iterable of mismatched keys. If None, a generic 97 message is returned. 98 """ 99 if event_type and event_type not in self._VALID_TYPES: 100 raise ValueError('event_type %s is not valid.' % event_type) 101 102 if event_result and event_result not in self._VALID_RESULTS: 103 raise ValueError('event_result %s is not valid.' % event_result) 104 105 self._expected_attrs = { 106 'event_type': event_type, 107 'event_result': event_result, 108 'version': version, 109 'previous_version': previous_version, 110 } 111 self._on_error = on_error 112 113 114 @staticmethod 115 def _attr_val_str(attr_val, helper_dict, default=None): 116 """Returns an enriched attribute value string, or default.""" 117 if not attr_val: 118 return default 119 120 s = str(attr_val) 121 if helper_dict: 122 s += ':%s' % helper_dict.get(attr_val, 'unknown') 123 124 return s 125 126 127 def _attr_name_and_values(self, attr_name, expected_attr_val, 128 actual_attr_val=None): 129 """Returns an attribute name, expected and actual value strings. 130 131 This will return (name, expected, actual); the returned value for 132 actual will be None if its respective input is None/empty. 133 134 """ 135 helper_dict = self._ATTR_NAME_DICT_MAP.get(attr_name) 136 expected_attr_val_str = self._attr_val_str(expected_attr_val, 137 helper_dict, 138 default='any') 139 actual_attr_val_str = self._attr_val_str(actual_attr_val, helper_dict) 140 141 return attr_name, expected_attr_val_str, actual_attr_val_str 142 143 144 def _attrs_to_str(self, attrs_dict): 145 return ' '.join(['%s=%s' % 146 self._attr_name_and_values(attr_name, attr_val)[0:2] 147 for attr_name, attr_val in attrs_dict.iteritems()]) 148 149 150 def __str__(self): 151 return self._attrs_to_str(self._expected_attrs) 152 153 154 def verify(self, actual_event): 155 """Verify the attributes of an actual event. 156 157 @param actual_event: a dictionary containing event attributes 158 159 @return An error message, or None if all attributes as expected. 160 161 """ 162 mismatched_attrs = [ 163 attr_name for attr_name, expected_attr_val 164 in self._expected_attrs.iteritems() 165 if (expected_attr_val and 166 not self._verify_attr(attr_name, expected_attr_val, 167 actual_event.get(attr_name)))] 168 if not mismatched_attrs: 169 return None 170 if callable(self._on_error): 171 return self._on_error(self._expected_attrs, actual_event, 172 mismatched_attrs) 173 if self._on_error is None: 174 return ('Received event (%s) does not match expectation (%s)' % 175 (self._attrs_to_str(actual_event), self)) 176 return self._on_error 177 178 179 def _verify_attr(self, attr_name, expected_attr_val, actual_attr_val): 180 """Verifies that an actual log event attributes matches expected on. 181 182 @param attr_name: name of the attribute to verify 183 @param expected_attr_val: expected attribute value 184 @param actual_attr_val: actual attribute value 185 186 @return True if actual value is present and matches, False otherwise. 187 188 """ 189 # None values are assumed to be missing and non-matching. 190 if actual_attr_val is None: 191 logging.error('No value found for %s (expected %s)', 192 *self._attr_name_and_values(attr_name, 193 expected_attr_val)[0:2]) 194 return False 195 196 # We allow expected version numbers (e.g. 2940.0.0) to be contained in 197 # actual values (2940.0.0-a1); this is necessary for the test to pass 198 # with developer / non-release images. 199 if (actual_attr_val == expected_attr_val or 200 ('version' in attr_name and expected_attr_val in actual_attr_val)): 201 return True 202 203 return False 204 205 206 def get_attrs(self): 207 """Returns a dictionary of expected attributes.""" 208 return dict(self._expected_attrs) 209 210 211class ExpectedUpdateEventChain(object): 212 """Defines a chain of expected update events.""" 213 def __init__(self): 214 self._expected_events_chain = [] 215 self._current_timestamp = None 216 217 218 def add_event(self, expected_events, timeout, on_timeout=None): 219 """Adds an expected event to the chain. 220 221 @param expected_events: The ExpectedEvent, or a list thereof, to wait 222 for. If a list is passed, it will wait for *any* 223 of the provided events, but only one of those. 224 @param timeout: A timeout (in seconds) to wait for the event. 225 @param on_timeout: An error string to use if the event times out. If 226 None, a generic message is used. 227 """ 228 if isinstance(expected_events, ExpectedUpdateEvent): 229 expected_events = [expected_events] 230 self._expected_events_chain.append( 231 (expected_events, timeout, on_timeout)) 232 233 234 @staticmethod 235 def _format_event_with_timeout(expected_events, timeout): 236 """Returns a string representation of the event, with timeout.""" 237 until = 'within %s seconds' % timeout if timeout else 'indefinitely' 238 return '%s, %s' % (' OR '.join(map(str, expected_events)), until) 239 240 241 def __str__(self): 242 return ('[%s]' % 243 ', '.join( 244 [self._format_event_with_timeout(expected_events, timeout) 245 for expected_events, timeout, _ 246 in self._expected_events_chain])) 247 248 249 def __repr__(self): 250 return str(self._expected_events_chain) 251 252 253 def verify(self, get_next_event): 254 """Verifies that an actual stream of events complies. 255 256 @param get_next_event: a function returning the next event 257 258 @raises ExpectedUpdateEventChainFailed if we failed to verify an event. 259 260 """ 261 for expected_events, timeout, on_timeout in self._expected_events_chain: 262 logging.info('Expecting %s', 263 self._format_event_with_timeout(expected_events, 264 timeout)) 265 err_msg = self._verify_event_with_timeout( 266 expected_events, timeout, on_timeout, get_next_event) 267 if err_msg is not None: 268 logging.error('Failed expected event: %s', err_msg) 269 raise ExpectedUpdateEventChainFailed(err_msg) 270 271 272 def _verify_event_with_timeout(self, expected_events, timeout, on_timeout, 273 get_next_event): 274 """Verify an expected event occurs within a given timeout. 275 276 @param expected_events: the list of possible events expected next 277 @param timeout: specified in seconds 278 @param on_timeout: A string to return if timeout occurs, or None. 279 @param get_next_event: function returning the next event in a stream 280 281 @return None if event complies, an error string otherwise. 282 283 """ 284 new_event = get_next_event() 285 if new_event: 286 # If this is the first event, set it as the current time 287 if self._current_timestamp is None: 288 self._current_timestamp = datetime.strptime(new_event[ 289 'timestamp'], 290 '%Y-%m-%d %H:%M:%S') 291 292 # Get the time stamp for the current event and convert to datetime 293 timestamp = new_event['timestamp'] 294 event_timestamp = datetime.strptime(timestamp, '%Y-%m-%d %H:%M:%S') 295 296 # Add the timeout onto the timestamp to get its expiry 297 event_timeout = self._current_timestamp + timedelta(seconds=timeout) 298 299 # If the event happened before the timeout 300 if event_timestamp < event_timeout: 301 difference = event_timestamp - self._current_timestamp 302 logging.info('Event took %s seconds to fire during the ' 303 'update', difference.seconds) 304 results = [event.verify(new_event) for event in expected_events] 305 self._current_timestamp = event_timestamp 306 return None if None in results else ' AND '.join(results) 307 308 logging.error('Timeout expired') 309 if on_timeout is None: 310 return ('Waiting for event %s timed out after %d seconds' % 311 (' OR '.join(map(str, expected_events)), timeout)) 312 return on_timeout 313 314 315class UpdateEventLogVerifier(object): 316 """Verifies update event chains on a devserver update log.""" 317 def __init__(self, event_log_filename): 318 self._event_log_filename = event_log_filename 319 self._event_log = [] 320 self._num_consumed_events = 0 321 322 323 def verify_expected_events_chain(self, expected_event_chain): 324 """Verify a given event chain. 325 326 @param expected_event_chain: instance of expected event chain. 327 328 @raises ExpectedUpdateEventChainFailed if we failed to verify the an 329 event. 330 """ 331 expected_event_chain.verify(self._get_next_log_event) 332 333 334 def _get_next_log_event(self): 335 """Returns the next event in an event log. 336 337 Uses the filename handed to it during initialization to read the 338 host log from devserver used during the update. 339 340 @return The next new event in the host log, as reported by devserver; 341 None if no such event was found or an error occurred. 342 343 """ 344 # (Re)read event log from hostlog file, if necessary. 345 if len(self._event_log) <= self._num_consumed_events: 346 try: 347 with open(self._event_log_filename, 'r') as out_log: 348 self._event_log = json.loads(out_log.read()) 349 except Exception as e: 350 raise error.TestFail('Error while reading the hostlogs ' 351 'from devserver: %s' % e) 352 353 # Return next new event, if one is found. 354 if len(self._event_log) > self._num_consumed_events: 355 new_event = { 356 key: str(val) for key, val 357 in self._event_log[self._num_consumed_events].iteritems() 358 } 359 self._num_consumed_events += 1 360 logging.info('Consumed new event: %s', new_event) 361 return new_event 362 363 364class TestPlatform(object): 365 """An interface and factory for platform-dependent functionality.""" 366 367 # Named tuple containing urls for staged urls needed for test. 368 # source_url: url to find the update payload for the source image. 369 # source_stateful_url: url to find the stateful payload for the source 370 # image. 371 # target_url: url to find the update payload for the target image. 372 # target_stateful_url: url to find the stateful payload for the target 373 # image. 374 StagedURLs = collections.namedtuple( 375 'StagedURLs', 376 ['source_url', 'source_stateful_url', 'target_url', 377 'target_stateful_url']) 378 379 380 def __init__(self): 381 assert False, 'Cannot instantiate this interface' 382 383 384 @staticmethod 385 def create(host): 386 """Returns a TestPlatform implementation based on the host type. 387 388 *DO NOT* override this method. 389 390 @param host: a host object representing the DUT 391 392 @return A TestPlatform implementation. 393 """ 394 os_type = host.get_os_type() 395 if os_type in ('cros', 'moblab'): 396 return ChromiumOSTestPlatform(host) 397 398 raise error.TestError('Unknown OS type reported by host: %s' % os_type) 399 400 401 def initialize(self, autotest_devserver): 402 """Initialize the object. 403 404 @param autotest_devserver: Instance of client.common_lib.dev_server to 405 use to reach the devserver instance for this 406 build. 407 """ 408 raise NotImplementedError 409 410 411 def prep_artifacts(self, test_conf): 412 """Prepares update artifacts for the test. 413 414 The test config must include 'source_payload_uri' and 415 'target_payload_uri'. In addition, it may include platform-specific 416 values as determined by the test control file. 417 418 @param test_conf: Dictionary containing the test configuration. 419 420 @return A tuple of staged URLs. 421 422 @raise error.TestError on failure. 423 """ 424 raise NotImplementedError 425 426 427 def reboot_device(self): 428 """Reboots the device.""" 429 raise NotImplementedError 430 431 432 def prep_device_for_update(self, source_payload_uri): 433 """Prepares the device for update. 434 435 @param source_payload_uri: Source payload GS URI to install. 436 437 @raise error.TestError on failure. 438 """ 439 raise NotImplementedError 440 441 442 def get_active_slot(self): 443 """Returns the active boot slot of the device.""" 444 raise NotImplementedError 445 446 447 def start_update_perf(self, bindir): 448 """Starts performance monitoring (if available). 449 450 @param bindir: Directory containing test binary files. 451 """ 452 raise NotImplementedError 453 454 455 def stop_update_perf(self, resultdir): 456 """Stops performance monitoring and returns data (if available). 457 458 @param resultdir: Directory containing test result files. 459 @return Dictionary containing performance attributes. 460 """ 461 raise NotImplementedError 462 463 464 def trigger_update(self, target_payload_uri): 465 """Kicks off an update. 466 467 @param target_payload_uri: The GS URI to use for the update. 468 """ 469 raise NotImplementedError 470 471 472 def finalize_update(self): 473 """Performs post-update procedures.""" 474 raise NotImplementedError 475 476 477 def get_update_log(self, num_lines): 478 """Returns the update log. 479 480 @param num_lines: Number of log lines to return (tail), zero for all. 481 482 @return String containing the last |num_lines| from the update log. 483 """ 484 raise NotImplementedError 485 486 487 def check_device_after_update(self): 488 """Runs final sanity checks. 489 490 @raise error.TestError on failure. 491 """ 492 raise NotImplementedError 493 494 495 def oobe_triggers_update(self): 496 """Returns True if this host has an OOBE flow during which 497 it will perform an update check and perhaps an update. 498 One example of such a flow is Hands-Off Zero-Touch Enrollment. 499 500 @return Boolean indicating whether the DUT's OOBE triggers an update. 501 """ 502 raise NotImplementedError 503 504 505 def verify_version(self, version): 506 """Compares the OS version on the DUT with the provided version. 507 508 @param version: The version to compare with (string). 509 @raise error.TestFail if the versions differ. 510 """ 511 actual_version = self._host.get_release_version() 512 if actual_version != version: 513 err_msg = 'Failed to verify OS version. Expected %s, was %s' % ( 514 version, actual_version) 515 logging.error(err_msg) 516 raise error.TestFail(err_msg) 517 518 519class ChromiumOSTestPlatform(TestPlatform): 520 """A TestPlatform implementation for Chromium OS.""" 521 522 _STATEFUL_UPDATE_FILENAME = 'stateful.tgz' 523 524 def __init__(self, host): 525 self._host = host 526 self._autotest_devserver = None 527 self._staged_urls = None 528 self._perf_mon_pid = None 529 530 531 def _stage_payload(self, build_name, filename, archive_url=None): 532 """Stage the given payload onto the devserver. 533 534 Works for either a stateful or full/delta test payload. Expects the 535 gs_path or a combo of build_name + filename. 536 537 @param build_name: The build name e.g. x86-mario-release/<version>. 538 If set, assumes default gs archive bucket and 539 requires filename to be specified. 540 @param filename: In conjunction with build_name, this is the file you 541 are downloading. 542 @param archive_url: An optional GS archive location, if not using the 543 devserver's default. 544 545 @return URL of the staged payload on the server. 546 547 @raise error.TestError if there's a problem with staging. 548 549 """ 550 try: 551 self._autotest_devserver.stage_artifacts(image=build_name, 552 files=[filename], 553 archive_url=archive_url) 554 return self._autotest_devserver.get_staged_file_url(filename, 555 build_name) 556 except dev_server.DevServerException, e: 557 raise error.TestError('Failed to stage payload: %s' % e) 558 559 560 def _stage_payload_by_uri(self, payload_uri): 561 """Stage a payload based on its GS URI. 562 563 This infers the build's label, filename and GS archive from the 564 provided GS URI. 565 566 @param payload_uri: The full GS URI of the payload. 567 568 @return URL of the staged payload on the server. 569 570 @raise error.TestError if there's a problem with staging. 571 572 """ 573 archive_url, _, filename = payload_uri.rpartition('/') 574 build_name = urlparse.urlsplit(archive_url).path.strip('/') 575 return self._stage_payload(build_name, filename, 576 archive_url=archive_url) 577 578 579 def _get_stateful_uri(self, build_uri): 580 """Returns a complete GS URI of a stateful update given a build path.""" 581 return '/'.join([build_uri.rstrip('/'), self._STATEFUL_UPDATE_FILENAME]) 582 583 584 def _payload_to_stateful_uri(self, payload_uri): 585 """Given a payload GS URI, returns the corresponding stateful URI.""" 586 build_uri = payload_uri.rpartition('/')[0] 587 if build_uri.endswith('payloads'): 588 build_uri = build_uri.rpartition('/')[0] 589 return self._get_stateful_uri(build_uri) 590 591 592 @staticmethod 593 def _get_update_parameters_from_uri(payload_uri): 594 """Extract the two vars needed for cros_au from the Google Storage URI. 595 596 dev_server.auto_update needs two values from this test: 597 (1) A build_name string e.g samus-release/R60-9583.0.0 598 (2) A filename of the exact payload file to use for the update. This 599 payload needs to have already been staged on the devserver. 600 601 This function extracts those two values from a Google Storage URI. 602 603 @param payload_uri: Google Storage URI to extract values from 604 """ 605 archive_url, _, payload_file = payload_uri.rpartition('/') 606 build_name = urlparse.urlsplit(archive_url).path.strip('/') 607 608 # This test supports payload uris from two Google Storage buckets. 609 # They store their payloads slightly differently. One stores them in 610 # a separate payloads directory. E.g 611 # gs://chromeos-image-archive/samus-release/R60-9583.0.0/blah.bin 612 # gs://chromeos-releases/dev-channel/samus/9334.0.0/payloads/blah.bin 613 if build_name.endswith('payloads'): 614 build_name = build_name.rpartition('/')[0] 615 payload_file = 'payloads/' + payload_file 616 617 logging.debug('Extracted build_name: %s, payload_file: %s from %s.', 618 build_name, payload_file, payload_uri) 619 return build_name, payload_file 620 621 622 def _install_version(self, payload_uri, clobber_stateful=False): 623 """Install the specified host with the image given by the url. 624 625 @param payload_uri: GS URI used to compute values for devserver cros_au 626 @param clobber_stateful: force a reinstall of the stateful image. 627 """ 628 629 build_name, payload_file = self._get_update_parameters_from_uri( 630 payload_uri) 631 logging.info('Installing image %s on the DUT', payload_uri) 632 633 try: 634 ds = self._autotest_devserver 635 _, pid = ds.auto_update(host_name=self._host.hostname, 636 build_name=build_name, 637 force_update=True, 638 full_update=True, 639 log_dir=self._results_dir, 640 payload_filename=payload_file, 641 clobber_stateful=clobber_stateful) 642 except: 643 logging.fatal('ERROR: Failed to install image on the DUT.') 644 raise 645 return pid 646 647 648 def _stage_artifacts_onto_devserver(self, test_conf): 649 """Stages artifacts that will be used by the test onto the devserver. 650 651 @param test_conf: a dictionary containing test configuration values 652 653 @return a StagedURLs tuple containing the staged urls. 654 """ 655 logging.info('Staging images onto autotest devserver (%s)', 656 self._autotest_devserver.url()) 657 658 staged_source_url = None 659 source_payload_uri = test_conf['source_payload_uri'] 660 661 if source_payload_uri: 662 staged_source_url = self._stage_payload_by_uri(source_payload_uri) 663 664 # In order to properly install the source image using a full 665 # payload we'll also need the stateful update that comes with it. 666 # In general, tests may have their source artifacts in a different 667 # location than their payloads. This is determined by whether or 668 # not the source_archive_uri attribute is set; if it isn't set, 669 # then we derive it from the dirname of the source payload. 670 source_archive_uri = test_conf.get('source_archive_uri') 671 if source_archive_uri: 672 source_stateful_uri = self._get_stateful_uri(source_archive_uri) 673 else: 674 source_stateful_uri = self._payload_to_stateful_uri( 675 source_payload_uri) 676 677 staged_source_stateful_url = self._stage_payload_by_uri( 678 source_stateful_uri) 679 680 # Log source image URLs. 681 logging.info('Source full payload from %s staged at %s', 682 source_payload_uri, staged_source_url) 683 if staged_source_stateful_url: 684 logging.info('Source stateful update from %s staged at %s', 685 source_stateful_uri, staged_source_stateful_url) 686 687 target_payload_uri = test_conf['target_payload_uri'] 688 staged_target_url = self._stage_payload_by_uri(target_payload_uri) 689 target_stateful_uri = None 690 staged_target_stateful_url = None 691 target_archive_uri = test_conf.get('target_archive_uri') 692 if target_archive_uri: 693 target_stateful_uri = self._get_stateful_uri(target_archive_uri) 694 else: 695 target_stateful_uri = self._payload_to_stateful_uri( 696 target_payload_uri) 697 698 if not staged_target_stateful_url and target_stateful_uri: 699 staged_target_stateful_url = self._stage_payload_by_uri( 700 target_stateful_uri) 701 702 # Log target payload URLs. 703 logging.info('%s test payload from %s staged at %s', 704 test_conf['update_type'], target_payload_uri, 705 staged_target_url) 706 logging.info('Target stateful update from %s staged at %s', 707 target_stateful_uri, staged_target_stateful_url) 708 709 return self.StagedURLs(staged_source_url, staged_source_stateful_url, 710 staged_target_url, staged_target_stateful_url) 711 712 713 def _run_login_test(self, tag): 714 """Runs login_LoginSuccess test on the DUT.""" 715 client_at = autotest.Autotest(self._host) 716 client_at.run_test('login_LoginSuccess', tag=tag) 717 718 719 # Interface overrides. 720 # 721 def initialize(self, autotest_devserver, results_dir): 722 self._autotest_devserver = autotest_devserver 723 self._results_dir = results_dir 724 725 726 def reboot_device(self): 727 self._host.reboot() 728 729 730 def prep_artifacts(self, test_conf): 731 self._staged_urls = self._stage_artifacts_onto_devserver(test_conf) 732 return self._staged_urls 733 734 735 def prep_device_for_update(self, source_payload_uri): 736 # Install the source version onto the DUT. 737 if self._staged_urls.source_url: 738 self._install_version(source_payload_uri, clobber_stateful=True) 739 740 # Make sure we can login before the target update. 741 self._run_login_test('source_update') 742 743 744 def get_active_slot(self): 745 return self._host.run('rootdev -s').stdout.strip() 746 747 748 def start_update_perf(self, bindir): 749 """Copy performance monitoring script to DUT. 750 751 The updater will kick off the script during the update. 752 """ 753 path = os.path.join(bindir, UPDATE_ENGINE_PERF_SCRIPT) 754 self._host.send_file(path, UPDATE_ENGINE_PERF_PATH) 755 756 757 def stop_update_perf(self, resultdir): 758 """ Copy the performance metrics back from the DUT.""" 759 try: 760 path = os.path.join('/var/log', UPDATE_ENGINE_PERF_RESULTS_FILE) 761 self._host.get_file(path, resultdir) 762 self._host.run('rm %s' % path) 763 script = os.path.join(UPDATE_ENGINE_PERF_PATH, 764 UPDATE_ENGINE_PERF_SCRIPT) 765 self._host.run('rm %s' % script) 766 return os.path.join(resultdir, UPDATE_ENGINE_PERF_RESULTS_FILE) 767 except: 768 logging.debug('Failed to copy performance metrics from DUT.') 769 return None 770 771 772 def trigger_update(self, target_payload_uri): 773 logging.info('Updating device to target image.') 774 return self._install_version(target_payload_uri) 775 776 def finalize_update(self): 777 # Stateful update is controlled by cros_au 778 pass 779 780 781 def get_update_log(self, num_lines): 782 return self._host.run_output( 783 'tail -n %d /var/log/update_engine.log' % num_lines, 784 stdout_tee=None) 785 786 787 def check_device_after_update(self): 788 # Make sure we can login after update. 789 self._run_login_test('target_update') 790 791 792 def oobe_triggers_update(self): 793 return self._host.oobe_triggers_update() 794 795 796class autoupdate_EndToEndTest(test.test): 797 """Complete update test between two Chrome OS releases. 798 799 Performs an end-to-end test of updating a ChromeOS device from one version 800 to another. The test performs the following steps: 801 802 1. Stages the source (full) and target update payload on the central 803 devserver. 804 2. Installs a source image on the DUT (if provided) and reboots to it. 805 3. Then starts the target update by calling cros_au RPC on the devserver. 806 4. This copies the devserver code and all payloads to the DUT. 807 5. Starts a devserver on the DUT. 808 6. Starts an update pointing to this local devserver. 809 7. Watches as the DUT applies the update to rootfs and stateful. 810 8. Reboots and repeats steps 5-6, ensuring that the next update check 811 shows the new image version. 812 9. Returns the hostlogs collected during each update check for 813 verification against expected update events. 814 815 Some notes on naming: 816 devserver: Refers to a machine running the Chrome OS Update Devserver. 817 autotest_devserver: An autotest wrapper to interact with a devserver. 818 Can be used to stage artifacts to a devserver. While 819 this can also be used to update a machine, we do not 820 use it for that purpose in this test as we manage 821 updates with out own devserver instances (see below). 822 *staged_url's: In this case staged refers to the fact that these items 823 are available to be downloaded statically from these urls 824 e.g. 'localhost:8080/static/my_file.gz'. These are usually 825 given after staging an artifact using a autotest_devserver 826 though they can be re-created given enough assumptions. 827 """ 828 version = 1 829 830 # Timeout periods, given in seconds. 831 _WAIT_FOR_INITIAL_UPDATE_CHECK_SECONDS = 12 * 60 832 # TODO(sosa): Investigate why this needs to be so long (this used to be 833 # 120 and regressed). 834 _WAIT_FOR_DOWNLOAD_STARTED_SECONDS = 4 * 60 835 # See https://crbug.com/731214 before changing WAIT_FOR_DOWNLOAD 836 _WAIT_FOR_DOWNLOAD_COMPLETED_SECONDS = 20 * 60 837 _WAIT_FOR_UPDATE_COMPLETED_SECONDS = 4 * 60 838 _WAIT_FOR_UPDATE_CHECK_AFTER_REBOOT_SECONDS = 15 * 60 839 840 # Logs and their whereabouts. 841 _WHERE_UPDATE_LOG = ('update_engine log (in sysinfo or on the DUT, also ' 842 'included in the test log)') 843 _WHERE_OMAHA_LOG = 'Omaha-devserver log (included in the test log)' 844 845 846 def initialize(self): 847 """Sets up variables that will be used by test.""" 848 self._host = None 849 self._omaha_devserver = None 850 self._source_image_installed = False 851 852 853 def cleanup(self): 854 """Kill the omaha devserver if it's still around.""" 855 if self._omaha_devserver: 856 self._omaha_devserver.stop_devserver() 857 858 self._omaha_devserver = None 859 860 861 def _get_hostlog_file(self, filename, pid): 862 """Return the hostlog file location. 863 864 @param filename: The partial filename to look for. 865 @param pid: The pid of the update. 866 867 """ 868 hosts = [self._host.hostname, self._host.ip] 869 for host in hosts: 870 hostlog = '%s_%s_%s' % (filename, host, pid) 871 file_url = os.path.join(self.job.resultdir, 872 dev_server.AUTO_UPDATE_LOG_DIR, 873 hostlog) 874 if os.path.exists(file_url): 875 return file_url 876 raise error.TestFail('Could not find %s for pid %s' % (filename, pid)) 877 878 879 def _dump_update_engine_log(self, test_platform): 880 """Dumps relevant AU error log.""" 881 try: 882 error_log = test_platform.get_update_log(80) 883 logging.error('Dumping snippet of update_engine log:\n%s', 884 snippet(error_log)) 885 except Exception: 886 # Mute any exceptions we get printing debug logs. 887 pass 888 889 890 def _report_perf_data(self, perf_file): 891 """Reports performance and resource data. 892 893 Currently, performance attributes are expected to include 'rss_peak' 894 (peak memory usage in bytes). 895 896 @param perf_file: A file with performance metrics. 897 """ 898 logging.debug('Reading perf results from %s.' % perf_file) 899 try: 900 with open(perf_file, 'r') as perf_file_handle: 901 perf_data = json.loads(perf_file_handle.read()) 902 except Exception as e: 903 logging.warning('Error while reading the perf data file: %s' % e) 904 return 905 906 rss_peak = perf_data.get('rss_peak') 907 if rss_peak: 908 rss_peak_kib = rss_peak / 1024 909 logging.info('Peak memory (RSS) usage on DUT: %d KiB', rss_peak_kib) 910 self.output_perf_value(description='mem_usage_peak', 911 value=int(rss_peak_kib), 912 units='KiB', 913 higher_is_better=False) 914 else: 915 logging.warning('No rss_peak key in JSON returned by %s', 916 UPDATE_ENGINE_PERF_SCRIPT) 917 918 919 def _error_initial_check(self, expected, actual, mismatched_attrs): 920 if 'version' in mismatched_attrs: 921 err_msg = ('Initial update check was received but the reported ' 922 'version is different from what was expected.') 923 if self._source_image_installed: 924 err_msg += (' The source payload we installed was probably ' 925 'incorrect or corrupt.') 926 else: 927 err_msg += (' The DUT is probably not running the correct ' 928 'source image.') 929 return err_msg 930 931 return 'A test bug occurred; inspect the test log.' 932 933 934 def _error_intermediate(self, expected, actual, mismatched_attrs, action, 935 problem): 936 if 'event_result' in mismatched_attrs: 937 event_result = actual.get('event_result') 938 reported = (('different than expected (%s)' % 939 EVENT_RESULT_DICT[event_result]) 940 if event_result else 'missing') 941 return ('The updater reported result code is %s. This could be an ' 942 'updater bug or a connectivity problem; check the %s. For ' 943 'a detailed log of update events, check the %s.' % 944 (reported, self._WHERE_UPDATE_LOG, self._WHERE_OMAHA_LOG)) 945 if 'event_type' in mismatched_attrs: 946 event_type = actual.get('event_type') 947 reported = ('different (%s)' % EVENT_TYPE_DICT[event_type] 948 if event_type else 'missing') 949 return ('Expected the updater to %s (%s) but received event type ' 950 'is %s. This could be an updater %s; check the ' 951 '%s. For a detailed log of update events, check the %s.' % 952 (action, EVENT_TYPE_DICT[expected['event_type']], reported, 953 problem, self._WHERE_UPDATE_LOG, self._WHERE_OMAHA_LOG)) 954 if 'version' in mismatched_attrs: 955 return ('The updater reported an unexpected version despite ' 956 'previously reporting the correct one. This is most likely ' 957 'a bug in update engine; check the %s.' % 958 self._WHERE_UPDATE_LOG) 959 960 return 'A test bug occurred; inspect the test log.' 961 962 963 def _error_download_started(self, expected, actual, mismatched_attrs): 964 return self._error_intermediate(expected, actual, mismatched_attrs, 965 'begin downloading', 966 'bug, crash or provisioning error') 967 968 969 def _error_download_finished(self, expected, actual, mismatched_attrs): 970 return self._error_intermediate(expected, actual, mismatched_attrs, 971 'finish downloading', 'bug or crash') 972 973 974 def _error_update_complete(self, expected, actual, mismatched_attrs): 975 return self._error_intermediate(expected, actual, mismatched_attrs, 976 'complete the update', 'bug or crash') 977 978 979 def _error_reboot_after_update(self, expected, actual, mismatched_attrs): 980 if 'event_result' in mismatched_attrs: 981 event_result = actual.get('event_result') 982 reported = ('different (%s)' % EVENT_RESULT_DICT[event_result] 983 if event_result else 'missing') 984 return ('The updater was expected to reboot (%s) but reported ' 985 'result code is %s. This could be a failure to reboot, an ' 986 'updater bug or a connectivity problem; check the %s and ' 987 'the system log. For a detailed log of update events, ' 988 'check the %s.' % 989 (EVENT_RESULT_DICT[expected['event_result']], reported, 990 self._WHERE_UPDATE_LOG, self._WHERE_OMAHA_LOG)) 991 if 'event_type' in mismatched_attrs: 992 event_type = actual.get('event_type') 993 reported = ('different (%s)' % EVENT_TYPE_DICT[event_type] 994 if event_type else 'missing') 995 return ('Expected to successfully reboot into the new image (%s) ' 996 'but received event type is %s. This probably means that ' 997 'the new image failed to verify after reboot, possibly ' 998 'because the payload is corrupt. This might also be an ' 999 'updater bug or crash; check the %s. For a detailed log of ' 1000 'update events, check the %s.' % 1001 (EVENT_TYPE_DICT[expected['event_type']], reported, 1002 self._WHERE_UPDATE_LOG, self._WHERE_OMAHA_LOG)) 1003 if 'version' in mismatched_attrs: 1004 return ('The DUT rebooted after the update but reports a different ' 1005 'image version than the one expected. This probably means ' 1006 'that the payload we applied was incorrect or corrupt.') 1007 if 'previous_version' in mismatched_attrs: 1008 return ('The DUT rebooted after the update and reports the ' 1009 'expected version. However, it reports a previous version ' 1010 'that is different from the one previously reported. This ' 1011 'is most likely a bug in update engine; check the %s.' % 1012 self._WHERE_UPDATE_LOG) 1013 1014 return 'A test bug occurred; inspect the test log.' 1015 1016 1017 def _timeout_err(self, desc, timeout, event_type=None): 1018 if event_type is not None: 1019 desc += ' (%s)' % EVENT_TYPE_DICT[event_type] 1020 return ('Failed to receive %s within %d seconds. This could be a ' 1021 'problem with the updater or a connectivity issue. For more ' 1022 'details, check the %s.' % 1023 (desc, timeout, self._WHERE_UPDATE_LOG)) 1024 1025 1026 def run_update_test(self, test_platform, test_conf): 1027 """Runs the actual update test once preconditions are met. 1028 1029 @param test_platform: TestPlatform implementation. 1030 @param test_conf: A dictionary containing test configuration values 1031 1032 @raises ExpectedUpdateEventChainFailed if we failed to verify an update 1033 event. 1034 """ 1035 1036 # Record the active root partition. 1037 source_active_slot = test_platform.get_active_slot() 1038 logging.info('Source active slot: %s', source_active_slot) 1039 1040 source_release = test_conf['source_release'] 1041 target_release = test_conf['target_release'] 1042 1043 test_platform.start_update_perf(self.bindir) 1044 try: 1045 # Update the DUT to the target image. 1046 pid = test_platform.trigger_update(test_conf['target_payload_uri']) 1047 1048 # Verify the host log that was returned from the update. 1049 file_url = self._get_hostlog_file('devserver_hostlog_rootfs', pid) 1050 1051 logging.info('Checking update steps with devserver hostlog file: ' 1052 '%s' % file_url) 1053 log_verifier = UpdateEventLogVerifier(file_url) 1054 1055 # Verify chain of events in a successful update process. 1056 chain = ExpectedUpdateEventChain() 1057 chain.add_event( 1058 ExpectedUpdateEvent( 1059 version=source_release, 1060 on_error=self._error_initial_check), 1061 self._WAIT_FOR_INITIAL_UPDATE_CHECK_SECONDS, 1062 on_timeout=self._timeout_err( 1063 'an initial update check', 1064 self._WAIT_FOR_INITIAL_UPDATE_CHECK_SECONDS)) 1065 chain.add_event( 1066 ExpectedUpdateEvent( 1067 event_type=EVENT_TYPE_DOWNLOAD_STARTED, 1068 event_result=EVENT_RESULT_SUCCESS, 1069 version=source_release, 1070 on_error=self._error_download_started), 1071 self._WAIT_FOR_DOWNLOAD_STARTED_SECONDS, 1072 on_timeout=self._timeout_err( 1073 'a download started notification', 1074 self._WAIT_FOR_DOWNLOAD_STARTED_SECONDS, 1075 event_type=EVENT_TYPE_DOWNLOAD_STARTED)) 1076 chain.add_event( 1077 ExpectedUpdateEvent( 1078 event_type=EVENT_TYPE_DOWNLOAD_FINISHED, 1079 event_result=EVENT_RESULT_SUCCESS, 1080 version=source_release, 1081 on_error=self._error_download_finished), 1082 self._WAIT_FOR_DOWNLOAD_COMPLETED_SECONDS, 1083 on_timeout=self._timeout_err( 1084 'a download finished notification', 1085 self._WAIT_FOR_DOWNLOAD_COMPLETED_SECONDS, 1086 event_type=EVENT_TYPE_DOWNLOAD_FINISHED)) 1087 chain.add_event( 1088 ExpectedUpdateEvent( 1089 event_type=EVENT_TYPE_UPDATE_COMPLETE, 1090 event_result=EVENT_RESULT_SUCCESS, 1091 version=source_release, 1092 on_error=self._error_update_complete), 1093 self._WAIT_FOR_UPDATE_COMPLETED_SECONDS, 1094 on_timeout=self._timeout_err( 1095 'an update complete notification', 1096 self._WAIT_FOR_UPDATE_COMPLETED_SECONDS, 1097 event_type=EVENT_TYPE_UPDATE_COMPLETE)) 1098 1099 log_verifier.verify_expected_events_chain(chain) 1100 1101 except: 1102 logging.fatal('ERROR: Failure occurred during the target update.') 1103 raise 1104 1105 perf_file = test_platform.stop_update_perf(self.job.resultdir) 1106 if perf_file is not None: 1107 self._report_perf_data(perf_file) 1108 1109 if test_platform.oobe_triggers_update(): 1110 # If DUT automatically checks for update during OOBE, 1111 # checking the post-update CrOS version and slot is sufficient. 1112 # This command checks the OS version. 1113 # The slot is checked a little later, after the else block. 1114 logging.info('Skipping post reboot update check.') 1115 test_platform.verify_version(target_release) 1116 else: 1117 # Observe post-reboot update check, which should indicate that the 1118 # image version has been updated. 1119 # Verify the host log that was returned from the update. 1120 file_url = self._get_hostlog_file('devserver_hostlog_reboot', pid) 1121 1122 logging.info('Checking post-reboot devserver hostlogs: %s' % 1123 file_url) 1124 log_verifier = UpdateEventLogVerifier(file_url) 1125 1126 chain = ExpectedUpdateEventChain() 1127 expected_events = [ 1128 ExpectedUpdateEvent( 1129 event_type=EVENT_TYPE_UPDATE_COMPLETE, 1130 event_result=EVENT_RESULT_SUCCESS_REBOOT, 1131 version=target_release, 1132 previous_version=source_release, 1133 on_error=self._error_reboot_after_update), 1134 # Newer versions send a "rebooted_after_update" message 1135 # after reboot with the previous version instead of another 1136 # "update_complete". 1137 ExpectedUpdateEvent( 1138 event_type=EVENT_TYPE_REBOOTED_AFTER_UPDATE, 1139 event_result=EVENT_RESULT_SUCCESS, 1140 version=target_release, 1141 previous_version=source_release, 1142 on_error=self._error_reboot_after_update), 1143 ] 1144 chain.add_event( 1145 expected_events, 1146 self._WAIT_FOR_UPDATE_CHECK_AFTER_REBOOT_SECONDS, 1147 on_timeout=self._timeout_err( 1148 'a successful reboot notification', 1149 self._WAIT_FOR_UPDATE_CHECK_AFTER_REBOOT_SECONDS, 1150 event_type=EVENT_TYPE_UPDATE_COMPLETE)) 1151 1152 log_verifier.verify_expected_events_chain(chain) 1153 1154 # Make sure we're using a different slot after the update. 1155 target_active_slot = test_platform.get_active_slot() 1156 if target_active_slot == source_active_slot: 1157 err_msg = 'The active image slot did not change after the update.' 1158 if None in (source_release, target_release): 1159 err_msg += (' The DUT likely rebooted into the old image, which ' 1160 'probably means that the payload we applied was ' 1161 'corrupt. But since we did not check the source ' 1162 'and/or target version we cannot say for sure.') 1163 elif source_release == target_release: 1164 err_msg += (' Given that the source and target versions are ' 1165 'identical, the DUT likely rebooted into the old ' 1166 'image. This probably means that the payload we ' 1167 'applied was corrupt.') 1168 else: 1169 err_msg += (' This is strange since the DUT reported the ' 1170 'correct target version. This is probably a system ' 1171 'bug; check the DUT system log.') 1172 raise error.TestFail(err_msg) 1173 1174 logging.info('Target active slot changed as expected: %s', 1175 target_active_slot) 1176 1177 logging.info('Update successful, test completed') 1178 1179 1180 def run_once(self, host, test_conf): 1181 """Performs a complete auto update test. 1182 1183 @param host: a host object representing the DUT 1184 @param test_conf: a dictionary containing test configuration values 1185 1186 @raise error.TestError if anything went wrong with setting up the test; 1187 error.TestFail if any part of the test has failed. 1188 """ 1189 self._host = host 1190 logging.debug('The test configuration supplied: %s', test_conf) 1191 1192 # Find a devserver to use. We first try to pick a devserver with the 1193 # least load. In case all devservers' load are higher than threshold, 1194 # fall back to the old behavior by picking a devserver based on the 1195 # payload URI, with which ImageServer.resolve will return a random 1196 # devserver based on the hash of the URI. 1197 # The picked devserver needs to respect the location of the host if 1198 # 'prefer_local_devserver' is set to True or 'restricted_subnets' is 1199 # set. 1200 hostname = self._host.hostname if self._host else None 1201 least_loaded_devserver = dev_server.get_least_loaded_devserver( 1202 hostname=hostname) 1203 if least_loaded_devserver: 1204 logging.debug('Choosing the least loaded devserver: %s', 1205 least_loaded_devserver) 1206 autotest_devserver = dev_server.ImageServer(least_loaded_devserver) 1207 else: 1208 logging.warning('No devserver meets the maximum load requirement. ' 1209 'Picking a random devserver to use.') 1210 autotest_devserver = dev_server.ImageServer.resolve( 1211 test_conf['target_payload_uri'], host.hostname) 1212 devserver_hostname = urlparse.urlparse( 1213 autotest_devserver.url()).hostname 1214 1215 logging.info('Devserver chosen for this run: %s', devserver_hostname) 1216 1217 # Obtain a test platform implementation. 1218 test_platform = TestPlatform.create(host) 1219 test_platform.initialize(autotest_devserver, self.job.resultdir) 1220 1221 # Stage source images and update payloads onto the devserver. 1222 staged_urls = test_platform.prep_artifacts(test_conf) 1223 self._source_image_installed = bool(staged_urls.source_url) 1224 1225 # Prepare the DUT (install source version etc). 1226 test_platform.prep_device_for_update(test_conf['source_payload_uri']) 1227 1228 # Start the update. 1229 try: 1230 self.run_update_test(test_platform, test_conf) 1231 except ExpectedUpdateEventChainFailed: 1232 self._dump_update_engine_log(test_platform) 1233 raise 1234 1235 test_platform.check_device_after_update() 1236