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 5import collections 6import json 7import logging 8import os 9import socket 10import time 11import urllib2 12import urlparse 13 14from autotest_lib.client.bin import utils as client_utils 15from autotest_lib.client.common_lib import error, global_config 16from autotest_lib.client.common_lib.cros import autoupdater, dev_server 17from autotest_lib.client.common_lib.cros.graphite import autotest_stats 18from autotest_lib.server import autotest, hosts, test 19from autotest_lib.server.cros.dynamic_suite import tools 20 21 22def _wait(secs, desc=None): 23 """Emits a log message and sleeps for a given number of seconds.""" 24 msg = 'Waiting %s seconds' % secs 25 if desc: 26 msg += ' (%s)' % desc 27 logging.info(msg) 28 time.sleep(secs) 29 30 31class ExpectedUpdateEventChainFailed(error.TestFail): 32 """Raised if we fail to receive an expected event in a chain.""" 33 34class RequiredArgumentMissing(error.TestError): 35 """Raised if the test is missing a required argument.""" 36 37 38# Update event types. 39EVENT_TYPE_DOWNLOAD_COMPLETE = '1' 40EVENT_TYPE_INSTALL_COMPLETE = '2' 41EVENT_TYPE_UPDATE_COMPLETE = '3' 42EVENT_TYPE_DOWNLOAD_STARTED = '13' 43EVENT_TYPE_DOWNLOAD_FINISHED = '14' 44EVENT_TYPE_REBOOTED_AFTER_UPDATE = '54' 45 46# Update event results. 47EVENT_RESULT_ERROR = '0' 48EVENT_RESULT_SUCCESS = '1' 49EVENT_RESULT_SUCCESS_REBOOT = '2' 50EVENT_RESULT_UPDATE_DEFERRED = '9' 51 52# Omaha event types/results, from update_engine/omaha_request_action.h 53# These are stored in dict form in order to easily print out the keys. 54EVENT_TYPE_DICT = { 55 EVENT_TYPE_DOWNLOAD_COMPLETE: 'download_complete', 56 EVENT_TYPE_INSTALL_COMPLETE: 'install_complete', 57 EVENT_TYPE_UPDATE_COMPLETE: 'update_complete', 58 EVENT_TYPE_DOWNLOAD_STARTED: 'download_started', 59 EVENT_TYPE_DOWNLOAD_FINISHED: 'download_finished', 60 EVENT_TYPE_REBOOTED_AFTER_UPDATE: 'rebooted_after_update' 61} 62 63EVENT_RESULT_DICT = { 64 EVENT_RESULT_ERROR: 'error', 65 EVENT_RESULT_SUCCESS: 'success', 66 EVENT_RESULT_SUCCESS_REBOOT: 'success_reboot', 67 EVENT_RESULT_UPDATE_DEFERRED: 'update_deferred' 68} 69 70 71def snippet(text): 72 """Returns the text with start/end snip markers around it. 73 74 @param text: The snippet text. 75 76 @return The text with start/end snip markers around it. 77 """ 78 snip = '---8<---' * 10 79 start = '-- START -' 80 end = '-- END -' 81 return ('%s%s\n%s\n%s%s' % 82 (start, snip[len(start):], text, end, snip[len(end):])) 83 84 85class ExpectedUpdateEvent(object): 86 """Defines an expected event in an update process.""" 87 88 _ATTR_NAME_DICT_MAP = { 89 'event_type': EVENT_TYPE_DICT, 90 'event_result': EVENT_RESULT_DICT, 91 } 92 93 _VALID_TYPES = set(EVENT_TYPE_DICT.keys()) 94 _VALID_RESULTS = set(EVENT_RESULT_DICT.keys()) 95 96 def __init__(self, event_type=None, event_result=None, version=None, 97 previous_version=None, on_error=None): 98 """Initializes an event expectation. 99 100 @param event_type: Expected event type. 101 @param event_result: Expected event result code. 102 @param version: Expected reported image version. 103 @param previous_version: Expected reported previous image version. 104 @param on_error: This is either an object to be returned when a received 105 event mismatches the expectation, or a callable used 106 for generating one. In the latter case, takes as 107 input two attribute dictionaries (expected and actual) 108 and an iterable of mismatched keys. If None, a generic 109 message is returned. 110 """ 111 if event_type and event_type not in self._VALID_TYPES: 112 raise ValueError('event_type %s is not valid.' % event_type) 113 114 if event_result and event_result not in self._VALID_RESULTS: 115 raise ValueError('event_result %s is not valid.' % event_result) 116 117 self._expected_attrs = { 118 'event_type': event_type, 119 'event_result': event_result, 120 'version': version, 121 'previous_version': previous_version, 122 } 123 self._on_error = on_error 124 125 126 @staticmethod 127 def _attr_val_str(attr_val, helper_dict, default=None): 128 """Returns an enriched attribute value string, or default.""" 129 if not attr_val: 130 return default 131 132 s = str(attr_val) 133 if helper_dict: 134 s += ':%s' % helper_dict.get(attr_val, 'unknown') 135 136 return s 137 138 139 def _attr_name_and_values(self, attr_name, expected_attr_val, 140 actual_attr_val=None): 141 """Returns an attribute name, expected and actual value strings. 142 143 This will return (name, expected, actual); the returned value for 144 actual will be None if its respective input is None/empty. 145 146 """ 147 helper_dict = self._ATTR_NAME_DICT_MAP.get(attr_name) 148 expected_attr_val_str = self._attr_val_str(expected_attr_val, 149 helper_dict, 150 default='any') 151 actual_attr_val_str = self._attr_val_str(actual_attr_val, helper_dict) 152 153 return attr_name, expected_attr_val_str, actual_attr_val_str 154 155 156 def _attrs_to_str(self, attrs_dict): 157 return ' '.join(['%s=%s' % 158 self._attr_name_and_values(attr_name, attr_val)[0:2] 159 for attr_name, attr_val in attrs_dict.iteritems()]) 160 161 162 def __str__(self): 163 return self._attrs_to_str(self._expected_attrs) 164 165 166 def verify(self, actual_event): 167 """Verify the attributes of an actual event. 168 169 @param actual_event: a dictionary containing event attributes 170 171 @return An error message, or None if all attributes as expected. 172 173 """ 174 mismatched_attrs = [ 175 attr_name for attr_name, expected_attr_val 176 in self._expected_attrs.iteritems() 177 if (expected_attr_val and 178 not self._verify_attr(attr_name, expected_attr_val, 179 actual_event.get(attr_name)))] 180 if not mismatched_attrs: 181 return None 182 if callable(self._on_error): 183 return self._on_error(self._expected_attrs, actual_event, 184 mismatched_attrs) 185 if self._on_error is None: 186 return ('Received event (%s) does not match expectation (%s)' % 187 (self._attrs_to_str(actual_event), self)) 188 return self._on_error 189 190 191 def _verify_attr(self, attr_name, expected_attr_val, actual_attr_val): 192 """Verifies that an actual log event attributes matches expected on. 193 194 @param attr_name: name of the attribute to verify 195 @param expected_attr_val: expected attribute value 196 @param actual_attr_val: actual attribute value 197 198 @return True if actual value is present and matches, False otherwise. 199 200 """ 201 # None values are assumed to be missing and non-matching. 202 if actual_attr_val is None: 203 logging.error('No value found for %s (expected %s)', 204 *self._attr_name_and_values(attr_name, 205 expected_attr_val)[0:2]) 206 return False 207 208 # We allow expected version numbers (e.g. 2940.0.0) to be contained in 209 # actual values (2940.0.0-a1); this is necessary for the test to pass 210 # with developer / non-release images. 211 if (actual_attr_val == expected_attr_val or 212 ('version' in attr_name and expected_attr_val in actual_attr_val)): 213 return True 214 215 return False 216 217 218 def get_attrs(self): 219 """Returns a dictionary of expected attributes.""" 220 return dict(self._expected_attrs) 221 222 223class ExpectedUpdateEventChain(object): 224 """Defines a chain of expected update events.""" 225 def __init__(self): 226 self._expected_events_chain = [] 227 228 229 def add_event(self, expected_events, timeout, on_timeout=None): 230 """Adds an expected event to the chain. 231 232 @param expected_events: The ExpectedEvent, or a list thereof, to wait 233 for. If a list is passed, it will wait for *any* 234 of the provided events, but only one of those. 235 @param timeout: A timeout (in seconds) to wait for the event. 236 @param on_timeout: An error string to use if the event times out. If 237 None, a generic message is used. 238 """ 239 if isinstance(expected_events, ExpectedUpdateEvent): 240 expected_events = [expected_events] 241 self._expected_events_chain.append( 242 (expected_events, timeout, on_timeout)) 243 244 245 @staticmethod 246 def _format_event_with_timeout(expected_events, timeout): 247 """Returns a string representation of the event, with timeout.""" 248 until = 'within %s seconds' % timeout if timeout else 'indefinitely' 249 return '%s, %s' % (' OR '.join(map(str, expected_events)), until) 250 251 252 def __str__(self): 253 return ('[%s]' % 254 ', '.join( 255 [self._format_event_with_timeout(expected_events, timeout) 256 for expected_events, timeout, _ 257 in self._expected_events_chain])) 258 259 260 def __repr__(self): 261 return str(self._expected_events_chain) 262 263 264 def verify(self, get_next_event): 265 """Verifies that an actual stream of events complies. 266 267 @param get_next_event: a function returning the next event 268 269 @raises ExpectedUpdateEventChainFailed if we failed to verify an event. 270 271 """ 272 for expected_events, timeout, on_timeout in self._expected_events_chain: 273 logging.info('Expecting %s', 274 self._format_event_with_timeout(expected_events, 275 timeout)) 276 err_msg = self._verify_event_with_timeout( 277 expected_events, timeout, on_timeout, get_next_event) 278 if err_msg is not None: 279 logging.error('Failed expected event: %s', err_msg) 280 raise ExpectedUpdateEventChainFailed(err_msg) 281 282 283 @staticmethod 284 def _verify_event_with_timeout(expected_events, timeout, on_timeout, 285 get_next_event): 286 """Verify an expected event occurs within a given timeout. 287 288 @param expected_events: the list of possible events expected next 289 @param timeout: specified in seconds 290 @param on_timeout: A string to return if timeout occurs, or None. 291 @param get_next_event: function returning the next event in a stream 292 293 @return None if event complies, an error string otherwise. 294 295 """ 296 base_timestamp = curr_timestamp = time.time() 297 expired_timestamp = base_timestamp + timeout 298 while curr_timestamp <= expired_timestamp: 299 new_event = get_next_event() 300 if new_event: 301 logging.info('Event received after %s seconds', 302 round(curr_timestamp - base_timestamp, 1)) 303 results = [event.verify(new_event) for event in expected_events] 304 return None if None in results else ' AND '.join(results) 305 306 # No new events, sleep for one second only (so we don't miss 307 # events at the end of the allotted timeout). 308 time.sleep(1) 309 curr_timestamp = time.time() 310 311 logging.error('Timeout expired') 312 if on_timeout is None: 313 return ('Waiting for event %s timed out after %d seconds' % 314 (' OR '.join(map(str, expected_events)), timeout)) 315 return on_timeout 316 317 318class UpdateEventLogVerifier(object): 319 """Verifies update event chains on a devserver update log.""" 320 def __init__(self, event_log_url, url_request_timeout=None): 321 self._event_log_url = event_log_url 322 self._url_request_timeout = url_request_timeout 323 self._event_log = [] 324 self._num_consumed_events = 0 325 326 327 def verify_expected_events_chain(self, expected_event_chain): 328 """Verify a given event chain. 329 330 @param expected_event_chain: instance of expected event chain. 331 332 @raises ExpectedUpdateEventChainFailed if we failed to verify the an 333 event. 334 """ 335 expected_event_chain.verify(self._get_next_log_event) 336 337 338 def _get_next_log_event(self): 339 """Returns the next event in an event log. 340 341 Uses the URL handed to it during initialization to obtain the host log 342 from a devserver. If new events are encountered, the first of them is 343 consumed and returned. 344 345 @return The next new event in the host log, as reported by devserver; 346 None if no such event was found or an error occurred. 347 348 """ 349 # (Re)read event log from devserver, if necessary. 350 if len(self._event_log) <= self._num_consumed_events: 351 try: 352 if self._url_request_timeout: 353 conn = urllib2.urlopen(self._event_log_url, 354 timeout=self._url_request_timeout) 355 else: 356 conn = urllib2.urlopen(self._event_log_url) 357 except urllib2.URLError, e: 358 logging.warning('Failed to read event log url: %s', e) 359 return None 360 except socket.timeout, e: 361 logging.warning('Timed out reading event log url: %s', e) 362 return None 363 364 event_log_resp = conn.read() 365 conn.close() 366 self._event_log = json.loads(event_log_resp) 367 368 # Return next new event, if one is found. 369 if len(self._event_log) > self._num_consumed_events: 370 new_event = { 371 key: str(val) for key, val 372 in self._event_log[self._num_consumed_events].iteritems() 373 } 374 self._num_consumed_events += 1 375 logging.info('Consumed new event: %s', new_event) 376 return new_event 377 378 379class OmahaDevserverFailedToStart(error.TestError): 380 """Raised when a omaha devserver fails to start.""" 381 382 383class OmahaDevserver(object): 384 """Spawns a test-private devserver instance.""" 385 # How long to wait for a devserver to start. 386 _WAIT_FOR_DEVSERVER_STARTED_SECONDS = 30 387 388 # How long to sleep (seconds) between checks to see if a devserver is up. 389 _WAIT_SLEEP_INTERVAL = 1 390 391 # Max devserver execution time (seconds); used with timeout(1) to ensure we 392 # don't have defunct instances hogging the system. 393 _DEVSERVER_TIMELIMIT_SECONDS = 12 * 60 * 60 394 395 396 def __init__(self, omaha_host, devserver_dir, update_payload_staged_url): 397 """Starts a private devserver instance, operating at Omaha capacity. 398 399 @param omaha_host: host address where the devserver is spawned. 400 @param devserver_dir: path to the devserver source directory 401 @param update_payload_staged_url: URL to provision for update requests. 402 403 """ 404 if not update_payload_staged_url: 405 raise error.TestError('Missing update payload url') 406 407 self._omaha_host = omaha_host 408 self._devserver_pid = 0 409 self._devserver_port = 0 # Determined later from devserver portfile. 410 self._devserver_dir = devserver_dir 411 self._update_payload_staged_url = update_payload_staged_url 412 413 self._devserver_ssh = hosts.SSHHost(self._omaha_host, 414 user=os.environ['USER']) 415 416 # Temporary files for various devserver outputs. 417 self._devserver_logfile = None 418 self._devserver_stdoutfile = None 419 self._devserver_portfile = None 420 self._devserver_pidfile = None 421 self._devserver_static_dir = None 422 423 424 def _cleanup_devserver_files(self): 425 """Cleans up the temporary devserver files.""" 426 for filename in (self._devserver_logfile, self._devserver_stdoutfile, 427 self._devserver_portfile, self._devserver_pidfile): 428 if filename: 429 self._devserver_ssh.run('rm -f %s' % filename, 430 ignore_status=True) 431 432 if self._devserver_static_dir: 433 self._devserver_ssh.run('rm -rf %s' % self._devserver_static_dir, 434 ignore_status=True) 435 436 437 def _create_tempfile_on_devserver(self, label, dir=False): 438 """Creates a temporary file/dir on the devserver and returns its path. 439 440 @param label: Identifier for the file context (string, no whitespaces). 441 @param dir: If True, create a directory instead of a file. 442 443 @raises test.TestError: If we failed to invoke mktemp on the server. 444 @raises OmahaDevserverFailedToStart: If tempfile creation failed. 445 """ 446 remote_cmd = 'mktemp --tmpdir devserver-%s.XXXXXX' % label 447 if dir: 448 remote_cmd += ' --directory' 449 450 try: 451 result = self._devserver_ssh.run(remote_cmd, ignore_status=True) 452 except error.AutoservRunError as e: 453 self._log_and_raise_remote_ssh_error(e) 454 if result.exit_status != 0: 455 raise OmahaDevserverFailedToStart( 456 'Could not create a temporary %s file on the devserver, ' 457 'error output: "%s"' % (label, result.stderr)) 458 return result.stdout.strip() 459 460 @staticmethod 461 def _log_and_raise_remote_ssh_error(e): 462 """Logs failure to ssh remote, then raises a TestError.""" 463 logging.debug('Failed to ssh into the devserver: %s', e) 464 logging.error('If you are running this locally it means you did not ' 465 'configure ssh correctly.') 466 raise error.TestError('Failed to ssh into the devserver: %s' % e) 467 468 469 def _read_int_from_devserver_file(self, filename): 470 """Reads and returns an integer value from a file on the devserver.""" 471 return int(self._get_devserver_file_content(filename).strip()) 472 473 474 def _wait_for_devserver_to_start(self): 475 """Waits until the devserver starts within the time limit. 476 477 Infers and sets the devserver PID and serving port. 478 479 Raises: 480 OmahaDevserverFailedToStart: If the time limit is reached and we 481 cannot connect to the devserver. 482 """ 483 # Compute the overall timeout. 484 deadline = time.time() + self._WAIT_FOR_DEVSERVER_STARTED_SECONDS 485 486 # First, wait for port file to be filled and determine the server port. 487 logging.warning('Waiting for devserver to start up.') 488 while time.time() < deadline: 489 try: 490 self._devserver_pid = self._read_int_from_devserver_file( 491 self._devserver_pidfile) 492 self._devserver_port = self._read_int_from_devserver_file( 493 self._devserver_portfile) 494 logging.info('Devserver pid is %d, serving on port %d', 495 self._devserver_pid, self._devserver_port) 496 break 497 except Exception: # Couldn't read file or corrupt content. 498 time.sleep(self._WAIT_SLEEP_INTERVAL) 499 else: 500 try: 501 self._devserver_ssh.run_output('uptime') 502 except error.AutoservRunError as e: 503 logging.debug('Failed to run uptime on the devserver: %s', e) 504 raise OmahaDevserverFailedToStart( 505 'The test failed to find the pid/port of the omaha ' 506 'devserver after %d seconds. Check the dumped devserver ' 507 'logs and devserver load for more information.' % 508 self._WAIT_FOR_DEVSERVER_STARTED_SECONDS) 509 510 # Check that the server is reponsding to network requests. 511 logging.warning('Waiting for devserver to accept network requests.') 512 url = 'http://%s' % self.get_netloc() 513 while time.time() < deadline: 514 if dev_server.DevServer.devserver_healthy(url, timeout_min=0.1): 515 break 516 517 # TODO(milleral): Refactor once crbug.com/221626 is resolved. 518 time.sleep(self._WAIT_SLEEP_INTERVAL) 519 else: 520 raise OmahaDevserverFailedToStart( 521 'The test failed to establish a connection to the omaha ' 522 'devserver it set up on port %d. Check the dumped ' 523 'devserver logs for more information.' % 524 self._devserver_port) 525 526 527 def start_devserver(self): 528 """Starts the devserver and confirms it is up. 529 530 Raises: 531 test.TestError: If we failed to spawn the remote devserver. 532 OmahaDevserverFailedToStart: If the time limit is reached and we 533 cannot connect to the devserver. 534 """ 535 update_payload_url_base, update_payload_path = self._split_url( 536 self._update_payload_staged_url) 537 538 # Allocate temporary files for various server outputs. 539 self._devserver_logfile = self._create_tempfile_on_devserver('log') 540 self._devserver_stdoutfile = self._create_tempfile_on_devserver( 541 'stdout') 542 self._devserver_portfile = self._create_tempfile_on_devserver('port') 543 self._devserver_pidfile = self._create_tempfile_on_devserver('pid') 544 self._devserver_static_dir = self._create_tempfile_on_devserver( 545 'static', dir=True) 546 547 # Invoke the Omaha/devserver on the remote server. Will attempt to kill 548 # it with a SIGTERM after a predetermined timeout has elapsed, followed 549 # by SIGKILL if not dead within 30 seconds from the former signal. 550 cmdlist = [ 551 'timeout', '-s', 'TERM', '-k', '30', 552 str(self._DEVSERVER_TIMELIMIT_SECONDS), 553 '%s/devserver.py' % self._devserver_dir, 554 '--payload=%s' % update_payload_path, 555 '--port=0', 556 '--pidfile=%s' % self._devserver_pidfile, 557 '--portfile=%s' % self._devserver_portfile, 558 '--logfile=%s' % self._devserver_logfile, 559 '--remote_payload', 560 '--urlbase=%s' % update_payload_url_base, 561 '--max_updates=1', 562 '--host_log', 563 '--static_dir=%s' % self._devserver_static_dir, 564 ] 565 remote_cmd = '( %s ) </dev/null >%s 2>&1 &' % ( 566 ' '.join(cmdlist), self._devserver_stdoutfile) 567 568 logging.info('Starting devserver with %r', remote_cmd) 569 try: 570 self._devserver_ssh.run_output(remote_cmd) 571 except error.AutoservRunError as e: 572 self._log_and_raise_remote_ssh_error(e) 573 574 try: 575 self._wait_for_devserver_to_start() 576 except OmahaDevserverFailedToStart: 577 self._kill_remote_process() 578 self._dump_devserver_log() 579 self._cleanup_devserver_files() 580 raise 581 582 583 def _kill_remote_process(self): 584 """Kills the devserver and verifies it's down; clears the remote pid.""" 585 def devserver_down(): 586 """Ensure that the devserver process is down.""" 587 return not self._remote_process_alive() 588 589 if devserver_down(): 590 return 591 592 for signal in 'SIGTERM', 'SIGKILL': 593 remote_cmd = 'kill -s %s %s' % (signal, self._devserver_pid) 594 self._devserver_ssh.run(remote_cmd) 595 try: 596 client_utils.poll_for_condition( 597 devserver_down, sleep_interval=1, desc='devserver down') 598 break 599 except client_utils.TimeoutError: 600 logging.warning('Could not kill devserver with %s.', signal) 601 else: 602 logging.warning('Failed to kill devserver, giving up.') 603 604 self._devserver_pid = None 605 606 607 def _remote_process_alive(self): 608 """Tests whether the remote devserver process is running.""" 609 if not self._devserver_pid: 610 return False 611 remote_cmd = 'test -e /proc/%s' % self._devserver_pid 612 result = self._devserver_ssh.run(remote_cmd, ignore_status=True) 613 return result.exit_status == 0 614 615 616 def get_netloc(self): 617 """Returns the netloc (host:port) of the devserver.""" 618 if not (self._devserver_pid and self._devserver_port): 619 raise error.TestError('No running omaha/devserver') 620 621 return '%s:%s' % (self._omaha_host, self._devserver_port) 622 623 624 def get_update_url(self): 625 """Returns the update_url you can use to update via this server.""" 626 return urlparse.urlunsplit(('http', self.get_netloc(), '/update', 627 '', '')) 628 629 630 def _get_devserver_file_content(self, filename): 631 """Returns the content of a file on the devserver.""" 632 return self._devserver_ssh.run_output('cat %s' % filename, 633 stdout_tee=None) 634 635 636 def _get_devserver_log(self): 637 """Obtain the devserver output.""" 638 return self._get_devserver_file_content(self._devserver_logfile) 639 640 641 def _get_devserver_stdout(self): 642 """Obtain the devserver output in stdout and stderr.""" 643 return self._get_devserver_file_content(self._devserver_stdoutfile) 644 645 646 def _dump_devserver_log(self, logging_level=logging.ERROR): 647 """Dump the devserver log to the autotest log. 648 649 @param logging_level: logging level (from logging) to log the output. 650 """ 651 logging.log(logging_level, "Devserver stdout and stderr:\n" + 652 snippet(self._get_devserver_stdout())) 653 logging.log(logging_level, "Devserver log file:\n" + 654 snippet(self._get_devserver_log())) 655 656 657 @staticmethod 658 def _split_url(url): 659 """Splits a URL into the URL base and path.""" 660 split_url = urlparse.urlsplit(url) 661 url_base = urlparse.urlunsplit( 662 (split_url.scheme, split_url.netloc, '', '', '')) 663 url_path = split_url.path 664 return url_base, url_path.lstrip('/') 665 666 667 def stop_devserver(self): 668 """Kill remote process and wait for it to die, dump its output.""" 669 if not self._devserver_pid: 670 logging.error('No running omaha/devserver.') 671 return 672 673 logging.info('Killing omaha/devserver') 674 self._kill_remote_process() 675 logging.debug('Final devserver log before killing') 676 self._dump_devserver_log(logging.DEBUG) 677 self._cleanup_devserver_files() 678 679 680class TestPlatform(object): 681 """An interface and factory for platform-dependent functionality.""" 682 683 # Named tuple containing urls for staged urls needed for test. 684 # source_url: url to find the update payload for the source image. 685 # source_stateful_url: url to find the stateful payload for the source 686 # image. 687 # target_url: url to find the update payload for the target image. 688 # target_stateful_url: url to find the stateful payload for the target 689 # image. 690 StagedURLs = collections.namedtuple( 691 'StagedURLs', 692 ['source_url', 'source_stateful_url', 'target_url', 693 'target_stateful_url']) 694 695 696 def __init__(self): 697 assert False, 'Cannot instantiate this interface' 698 699 700 @staticmethod 701 def create(host): 702 """Returns a TestPlatform implementation based on the host type. 703 704 *DO NOT* override this method. 705 706 @param host: a host object representing the DUT 707 708 @return A TestPlatform implementation. 709 """ 710 os_type = host.get_os_type() 711 if os_type == 'cros': 712 return ChromiumOSTestPlatform(host) 713 if os_type == 'brillo': 714 return BrilloTestPlatform(host) 715 716 raise error.TestError('Unknown OS type reported by host: %s' % os_type) 717 718 719 def initialize(self, autotest_devserver, devserver_dir): 720 """Initialize the object. 721 722 @param autotest_devserver: Instance of client.common_lib.dev_server to 723 use to reach the devserver instance for this 724 build. 725 @param devserver_dir: Path to devserver source tree. 726 """ 727 raise NotImplementedError 728 729 730 def prep_artifacts(self, test_conf): 731 """Prepares update artifacts for the test. 732 733 The test config must include 'source_payload_uri' and 734 'target_payload_uri'. In addition, it may include platform-specific 735 values as determined by the test control file. 736 737 @param test_conf: Dictionary containing the test configuration. 738 739 @return A tuple of staged URLs. 740 741 @raise error.TestError on failure. 742 """ 743 raise NotImplementedError 744 745 746 def reboot_device(self): 747 """Reboots the device.""" 748 raise NotImplementedError 749 750 751 def prep_device_for_update(self, source_release): 752 """Prepares the device for update. 753 754 @param source_release: Source release version (string), or None. 755 756 @raise error.TestError on failure. 757 """ 758 raise NotImplementedError 759 760 761 def get_active_slot(self): 762 """Returns the active boot slot of the device.""" 763 raise NotImplementedError 764 765 766 def start_update_perf(self, bindir): 767 """Starts performance monitoring (if available). 768 769 @param bindir: Directory containing test binary files. 770 """ 771 raise NotImplementedError 772 773 774 def stop_update_perf(self): 775 """Stops performance monitoring and returns data (if available). 776 777 @return Dictionary containing performance attributes. 778 """ 779 raise NotImplementedError 780 781 782 def trigger_update(self, omaha_devserver): 783 """Kicks off an update. 784 785 @param omaha_devserver: OmahaDevserver instance. 786 """ 787 raise NotImplementedError 788 789 790 def finalize_update(self): 791 """Performs post-update procedures.""" 792 raise NotImplementedError 793 794 795 def get_update_log(self, num_lines): 796 """Returns the update log. 797 798 @param num_lines: Number of log lines to return (tail), zero for all. 799 800 @return String containing the last |num_lines| from the update log. 801 """ 802 raise NotImplementedError 803 804 805 def check_device_after_update(self, target_release): 806 """Runs final sanity checks. 807 808 @param target_release: Target release version (string), or None. 809 810 @raise error.TestError on failure. 811 """ 812 raise NotImplementedError 813 814 815class ChromiumOSTestPlatform(TestPlatform): 816 """A TestPlatform implementation for Chromium OS.""" 817 818 _STATEFUL_UPDATE_FILENAME = 'stateful.tgz' 819 _LOGINABLE_MINIMUM_RELEASE = 5110 820 821 def __init__(self, host): 822 self._host = host 823 self._autotest_devserver = None 824 self._devserver_dir = None 825 self._staged_urls = None 826 self._perf_mon_pid = None 827 828 829 def _stage_payload(self, devserver_label, filename, archive_url=None): 830 """Stage the given payload onto the devserver. 831 832 Works for either a stateful or full/delta test payload. Expects the 833 gs_path or a combo of devserver_label + filename. 834 835 @param devserver_label: The build name e.g. x86-mario-release/<version>. 836 If set, assumes default gs archive bucket and 837 requires filename to be specified. 838 @param filename: In conjunction with devserver_label, if just specifying 839 the devserver label name, this is which file are you 840 downloading. 841 @param archive_url: An optional GS archive location, if not using the 842 devserver's default. 843 844 @return URL of the staged payload on the server. 845 846 @raise error.TestError if there's a problem with staging. 847 848 """ 849 try: 850 self._autotest_devserver.stage_artifacts( 851 image=devserver_label, files=[filename], 852 archive_url=archive_url) 853 return self._autotest_devserver.get_staged_file_url(filename, 854 devserver_label) 855 except dev_server.DevServerException, e: 856 raise error.TestError('Failed to stage payload: %s' % e) 857 858 859 def _stage_payload_by_uri(self, payload_uri): 860 """Stage a payload based on its GS URI. 861 862 This infers the build's label, filename and GS archive from the 863 provided GS URI. 864 865 @param payload_uri: The full GS URI of the payload. 866 867 @return URL of the staged payload on the server. 868 869 @raise error.TestError if there's a problem with staging. 870 871 """ 872 archive_url, _, filename = payload_uri.rpartition('/') 873 devserver_label = urlparse.urlsplit(archive_url).path.strip('/') 874 return self._stage_payload(devserver_label, filename, 875 archive_url=archive_url) 876 877 878 @staticmethod 879 def _payload_to_update_url(payload_url): 880 """Given a update or stateful payload url, returns the update url.""" 881 # We want to transform it to the correct omaha url which is 882 # <hostname>/update/...LABEL. 883 base_url = payload_url.rpartition('/')[0] 884 return base_url.replace('/static/', '/update/') 885 886 887 def _get_stateful_uri(self, build_uri): 888 """Returns a complete GS URI of a stateful update given a build path.""" 889 return '/'.join([build_uri.rstrip('/'), self._STATEFUL_UPDATE_FILENAME]) 890 891 892 def _payload_to_stateful_uri(self, payload_uri): 893 """Given a payload GS URI, returns the corresponding stateful URI.""" 894 build_uri = payload_uri.rpartition('/')[0] 895 return self._get_stateful_uri(build_uri) 896 897 898 def _update_via_test_payloads(self, omaha_host, payload_url, stateful_url, 899 clobber): 900 """Given the following update and stateful urls, update the DUT. 901 902 Only updates the rootfs/stateful if the respective url is provided. 903 904 @param omaha_host: If updating rootfs, redirect updates through this 905 host. Should be None iff payload_url is None. 906 @param payload_url: If set, the specified url to find the update 907 payload. 908 @param stateful_url: If set, the specified url to find the stateful 909 payload. 910 @param clobber: If True, do a clean install of stateful. 911 """ 912 def perform_update(url, is_stateful): 913 """Perform a rootfs/stateful update using given URL. 914 915 @param url: URL to update from. 916 @param is_stateful: Whether this is a stateful or rootfs update. 917 """ 918 if url: 919 updater = autoupdater.ChromiumOSUpdater(url, host=self._host) 920 if is_stateful: 921 updater.update_stateful(clobber=clobber) 922 else: 923 updater.update_image() 924 925 # We create a OmahaDevserver to redirect blah.bin to update/. This 926 # allows us to use any payload filename to serve an update. 927 temp_devserver = None 928 try: 929 if payload_url: 930 temp_devserver = OmahaDevserver( 931 omaha_host, self._devserver_dir, payload_url) 932 temp_devserver.start_devserver() 933 payload_url = temp_devserver.get_update_url() 934 935 stateful_url = self._payload_to_update_url(stateful_url) 936 937 perform_update(payload_url, False) 938 perform_update(stateful_url, True) 939 finally: 940 if temp_devserver: 941 temp_devserver.stop_devserver() 942 943 944 def _install_source_version(self, devserver_hostname, image_url, 945 stateful_url): 946 """Prepare the specified host with the image given by the urls. 947 948 @param devserver_hostname: If updating rootfs, redirect updates 949 through this host. Should be None iff 950 image_url is None. 951 @param image_url: If set, the specified url to find the source image 952 or full payload for the source image. 953 @param stateful_url: If set, the specified url to find the stateful 954 payload. 955 """ 956 try: 957 # Reboot to get us into a clean state. 958 self._host.reboot() 959 # Since we are installing the source image of the test, clobber 960 # stateful. 961 self._update_via_test_payloads(devserver_hostname, image_url, 962 stateful_url, True) 963 self._host.reboot() 964 except OmahaDevserverFailedToStart as e: 965 logging.fatal('Failed to start private devserver for installing ' 966 'the source image (%s) on the DUT', image_url) 967 raise error.TestError( 968 'Failed to start private devserver for installing the ' 969 'source image on the DUT: %s' % e) 970 except error.AutoservRunError as e: 971 logging.fatal('Error re-imaging or rebooting the DUT with the ' 972 'source image from %s', image_url) 973 raise error.TestError('Failed to install the source image or ' 974 'reboot the DUT: %s' % e) 975 976 977 def _stage_artifacts_onto_devserver(self, test_conf): 978 """Stages artifacts that will be used by the test onto the devserver. 979 980 @param test_conf: a dictionary containing test configuration values 981 982 @return a StagedURLs tuple containing the staged urls. 983 """ 984 logging.info('Staging images onto autotest devserver (%s)', 985 self._autotest_devserver.url()) 986 987 staged_source_url = None 988 staged_source_stateful_url = None 989 try: 990 source_payload_uri = test_conf['source_payload_uri'] 991 except KeyError: 992 # TODO(garnold) Remove legacy key support once control files on all 993 # release branches have caught up. 994 source_payload_uri = test_conf['source_image_uri'] 995 if source_payload_uri: 996 staged_source_url = self._stage_payload_by_uri(source_payload_uri) 997 998 # In order to properly install the source image using a full 999 # payload we'll also need the stateful update that comes with it. 1000 # In general, tests may have their source artifacts in a different 1001 # location than their payloads. This is determined by whether or 1002 # not the source_archive_uri attribute is set; if it isn't set, 1003 # then we derive it from the dirname of the source payload. 1004 source_archive_uri = test_conf.get('source_archive_uri') 1005 if source_archive_uri: 1006 source_stateful_uri = self._get_stateful_uri(source_archive_uri) 1007 else: 1008 source_stateful_uri = self._payload_to_stateful_uri( 1009 source_payload_uri) 1010 1011 staged_source_stateful_url = self._stage_payload_by_uri( 1012 source_stateful_uri) 1013 1014 # Log source image URLs. 1015 logging.info('Source full payload from %s staged at %s', 1016 source_payload_uri, staged_source_url) 1017 if staged_source_stateful_url: 1018 logging.info('Source stateful update from %s staged at %s', 1019 source_stateful_uri, staged_source_stateful_url) 1020 1021 target_payload_uri = test_conf['target_payload_uri'] 1022 staged_target_url = self._stage_payload_by_uri(target_payload_uri) 1023 target_stateful_uri = None 1024 staged_target_stateful_url = None 1025 target_archive_uri = test_conf.get('target_archive_uri') 1026 if target_archive_uri: 1027 target_stateful_uri = self._get_stateful_uri(target_archive_uri) 1028 else: 1029 # Attempt to get the job_repo_url to find the stateful payload for 1030 # the target image. 1031 try: 1032 job_repo_url = self._host.lookup_job_repo_url() 1033 except KeyError: 1034 # If this failed, assume the stateful update is next to the 1035 # update payload. 1036 target_stateful_uri = self._payload_to_stateful_uri( 1037 target_payload_uri) 1038 else: 1039 _, devserver_label = tools.get_devserver_build_from_package_url( 1040 job_repo_url) 1041 staged_target_stateful_url = self._stage_payload( 1042 devserver_label, self._STATEFUL_UPDATE_FILENAME) 1043 1044 if not staged_target_stateful_url and target_stateful_uri: 1045 staged_target_stateful_url = self._stage_payload_by_uri( 1046 target_stateful_uri) 1047 1048 # Log target payload URLs. 1049 logging.info('%s test payload from %s staged at %s', 1050 test_conf['update_type'], target_payload_uri, 1051 staged_target_url) 1052 logging.info('Target stateful update from %s staged at %s', 1053 target_stateful_uri or 'standard location', 1054 staged_target_stateful_url) 1055 1056 return self.StagedURLs(staged_source_url, staged_source_stateful_url, 1057 staged_target_url, staged_target_stateful_url) 1058 1059 1060 def _run_login_test(self, release_string): 1061 """Runs login_LoginSuccess test if it is supported by the release.""" 1062 # Only do login tests with recent builds, since they depend on 1063 # some binary compatibility with the build itself. 1064 # '5116.0.0' -> ('5116', '0', '0') -> 5116 1065 if not release_string: 1066 logging.info('No release provided, skipping login test.') 1067 elif int(release_string.split('.')[0]) > self._LOGINABLE_MINIMUM_RELEASE: 1068 # Login, to prove we can before/after the update. 1069 logging.info('Attempting to login (release %s).', release_string) 1070 1071 client_at = autotest.Autotest(self._host) 1072 client_at.run_test('login_LoginSuccess') 1073 else: 1074 logging.info('Not attempting login test because %s is older than ' 1075 '%d.', release_string, self._LOGINABLE_MINIMUM_RELEASE) 1076 1077 1078 def _start_perf_mon(self, bindir): 1079 """Starts monitoring performance and resource usage on a DUT. 1080 1081 Call _stop_perf_mon() with the returned PID to stop monitoring 1082 and collect the results. 1083 1084 @param bindir: Directoy containing monitoring script. 1085 1086 @return The PID of the newly created DUT monitoring process. 1087 """ 1088 # We can't assume much about the source image so we copy the 1089 # performance monitoring script to the DUT directly. 1090 path = os.path.join(bindir, 'update_engine_performance_monitor.py') 1091 self._host.send_file(path, '/tmp') 1092 cmd = 'python /tmp/update_engine_performance_monitor.py --start-bg' 1093 return int(self._host.run(cmd).stdout) 1094 1095 1096 def _stop_perf_mon(self, perf_mon_pid): 1097 """Stops monitoring performance and resource usage on a DUT. 1098 1099 @param perf_mon_pid: the PID returned from _start_perf_mon(). 1100 1101 @return Dictionary containing performance attributes, or None if 1102 unavailable. 1103 """ 1104 # Gracefully handle problems with performance monitoring by 1105 # just returning None. 1106 try: 1107 cmd = ('python /tmp/update_engine_performance_monitor.py ' 1108 '--stop-bg=%d') % perf_mon_pid 1109 perf_json_txt = self._host.run(cmd).stdout 1110 return json.loads(perf_json_txt) 1111 except Exception as e: 1112 logging.warning('Failed to parse output from ' 1113 'update_engine_performance_monitor.py: %s', e) 1114 return None 1115 1116 1117 # Interface overrides. 1118 # 1119 def initialize(self, autotest_devserver, devserver_dir): 1120 self._autotest_devserver = autotest_devserver 1121 self._devserver_dir = devserver_dir 1122 1123 1124 def reboot_device(self): 1125 self._host.reboot() 1126 1127 1128 def prep_artifacts(self, test_conf): 1129 self._staged_urls = self._stage_artifacts_onto_devserver(test_conf) 1130 return self._staged_urls 1131 1132 1133 def prep_device_for_update(self, source_release): 1134 # Install the source version onto the DUT. 1135 if self._staged_urls.source_url: 1136 logging.info('Installing a source image on the DUT') 1137 devserver_hostname = urlparse.urlparse( 1138 self._autotest_devserver.url()).hostname 1139 self._install_source_version(devserver_hostname, 1140 self._staged_urls.source_url, 1141 self._staged_urls.source_stateful_url) 1142 1143 # Make sure we can login before the update. 1144 self._run_login_test(source_release) 1145 1146 1147 def get_active_slot(self): 1148 return self._host.run('rootdev -s').stdout.strip() 1149 1150 1151 def start_update_perf(self, bindir): 1152 if self._perf_mon_pid is None: 1153 self._perf_mon_pid = self._start_perf_mon(bindir) 1154 1155 1156 def stop_update_perf(self): 1157 perf_data = None 1158 if self._perf_mon_pid is not None: 1159 perf_data = self._stop_perf_mon(self._perf_mon_pid) 1160 self._perf_mon_pid = None 1161 1162 return perf_data 1163 1164 1165 def trigger_update(self, omaha_devserver): 1166 updater = autoupdater.ChromiumOSUpdater( 1167 omaha_devserver.get_update_url(), host=self._host) 1168 updater.trigger_update() 1169 1170 1171 def finalize_update(self): 1172 self._update_via_test_payloads( 1173 None, None, self._staged_urls.target_stateful_url, False) 1174 1175 1176 def get_update_log(self, num_lines): 1177 return self._host.run_output( 1178 'tail -n %d /var/log/update_engine.log' % num_lines, 1179 stdout_tee=None) 1180 1181 1182 def check_device_after_update(self, target_release): 1183 # Make sure we can login after update. 1184 self._run_login_test(target_release) 1185 1186 1187class BrilloTestPlatform(TestPlatform): 1188 """A TestPlatform implementation for Brillo.""" 1189 1190 _URL_DEFAULT_PORT = 80 1191 _DUT_LOCALHOST = '127.0.0.1' 1192 1193 def __init__(self, host): 1194 self._host = host 1195 self._autotest_devserver = None 1196 self._devserver_dir = None 1197 self._staged_urls = None 1198 self._forwarding_ports = set() 1199 1200 1201 @classmethod 1202 def _get_host_port(cls, url): 1203 """Returns the host and port values from a given URL. 1204 1205 @param url: The URL from which the values are extracted. 1206 1207 @return A pair consisting of the host and port strings. 1208 """ 1209 host, _, port = urlparse.urlsplit(url).netloc.partition(':') 1210 return host, port or str(cls._URL_DEFAULT_PORT) 1211 1212 1213 def _install_rev_forwarding(self, port=None): 1214 """Installs reverse forwarding rules via ADB. 1215 1216 @param port: The TCP port we want forwarded; if None, installs all 1217 previously configured ports. 1218 """ 1219 ports = self._forwarding_ports if port is None else [port] 1220 for port in ports: 1221 port_spec = 'tcp:%s' % port 1222 self._host.add_forwarding(port_spec, port_spec, reverse=True) 1223 1224 1225 def _add_rev_forwarding(self, url): 1226 """Configures reverse port forwarding and adjusts the given URL. 1227 1228 This extracts the port from the URL, adds it to the set of configured 1229 forwarding ports, installs it to the DUT, then returns the adjusted URL 1230 for use by the DUT. 1231 1232 @param url: The URL for which we need to establish forwarding. 1233 1234 @return: The adjusted URL for use on the DUT. 1235 """ 1236 if url: 1237 host, port = self._get_host_port(url) 1238 if port not in self._forwarding_ports: 1239 self._forwarding_ports.add(port) 1240 self._install_rev_forwarding(port=port) 1241 url = url.replace(host, self._DUT_LOCALHOST, 1) 1242 return url 1243 1244 1245 def _remove_rev_forwarding(self, url=None): 1246 """Removes a reverse port forwarding. 1247 1248 @param url: The URL for which forwarding was established; if None, 1249 removes all previously configured ports. 1250 """ 1251 ports = set() 1252 if url is None: 1253 ports.update(self._forwarding_ports) 1254 else: 1255 _, port = self._get_host_port(url) 1256 if port in self._forwarding_ports: 1257 ports.add(port) 1258 1259 # TODO(garnold) Enable once ADB port removal is fixed (b/24771474): 1260 # for port in ports: 1261 # self._host.remove_forwarding(src='tcp:%s' % port, reverse=True) 1262 1263 self._forwarding_ports.difference_update(ports) 1264 1265 1266 def _install_source_version(self, devserver_hostname, payload_url): 1267 """Installs a source version onto the test device. 1268 1269 @param devserver_hostname: Redirect updates through this host. 1270 @param payload_url: URL of staged payload for installing a source image. 1271 """ 1272 try: 1273 # Start a private Omaha server and update the DUT. 1274 temp_devserver = None 1275 url = None 1276 try: 1277 temp_devserver = OmahaDevserver( 1278 devserver_hostname, self._devserver_dir, payload_url) 1279 temp_devserver.start_devserver() 1280 url = self._add_rev_forwarding(temp_devserver.get_update_url()) 1281 updater = autoupdater.BrilloUpdater(url, host=self._host) 1282 updater.update_image() 1283 finally: 1284 if url: 1285 self._remove_rev_forwarding(url) 1286 if temp_devserver: 1287 temp_devserver.stop_devserver() 1288 1289 # Reboot the DUT. 1290 self.reboot_device() 1291 except OmahaDevserverFailedToStart as e: 1292 logging.fatal('Failed to start private devserver for installing ' 1293 'the source payload (%s) on the DUT', payload_url) 1294 raise error.TestError( 1295 'Failed to start private devserver for installing the ' 1296 'source image on the DUT: %s' % e) 1297 except error.AutoservRunError as e: 1298 logging.fatal('Error re-imaging or rebooting the DUT with the ' 1299 'source image from %s', payload_url) 1300 raise error.TestError('Failed to install the source image or ' 1301 'reboot the DUT: %s' % e) 1302 1303 1304 # Interface overrides. 1305 # 1306 def initialize(self, autotest_devserver, devserver_dir): 1307 self._autotest_devserver = autotest_devserver 1308 self._devserver_dir = devserver_dir 1309 1310 1311 def reboot_device(self): 1312 self._host.reboot() 1313 self._install_rev_forwarding() 1314 1315 1316 def prep_artifacts(self, test_conf): 1317 # TODO(garnold) Currently we don't stage anything and assume that the 1318 # provided URLs are of pre-staged payloads. We should implement staging 1319 # support once a release scheme for Brillo is finalized. 1320 self._staged_urls = self.StagedURLs( 1321 self._add_rev_forwarding(test_conf['source_payload_uri']), None, 1322 self._add_rev_forwarding(test_conf['target_payload_uri']), None) 1323 return self._staged_urls 1324 1325 1326 def prep_device_for_update(self, source_release): 1327 # Install the source version onto the DUT. 1328 if self._staged_urls.source_url: 1329 logging.info('Installing a source image on the DUT') 1330 devserver_hostname = urlparse.urlparse( 1331 self._autotest_devserver.url()).hostname 1332 self._install_source_version(devserver_hostname, 1333 self._staged_urls.source_url) 1334 1335 1336 def get_active_slot(self): 1337 return self._host.run('rootdev -s /system').stdout.strip() 1338 1339 1340 def start_update_perf(self, bindir): 1341 pass 1342 1343 1344 def stop_update_perf(self): 1345 pass 1346 1347 1348 def trigger_update(self, omaha_devserver): 1349 url = self._add_rev_forwarding(omaha_devserver.get_update_url()) 1350 updater = autoupdater.BrilloUpdater(url, host=self._host) 1351 updater.trigger_update() 1352 1353 1354 def finalize_update(self): 1355 pass 1356 1357 1358 def get_update_log(self, num_lines): 1359 return self._host.run_output( 1360 'logcat -d -s update_engine | tail -n %d' % num_lines, 1361 stdout_tee=None) 1362 1363 1364 def check_device_after_update(self, target_release): 1365 self._remove_rev_forwarding() 1366 # TODO(garnold) Port forwarding removal is broken in ADB (b/24771474). 1367 # Instead we reboot the device, which has the side-effect of flushing 1368 # all forwarding rules. Once fixed, the following should be removed. 1369 self.reboot_device() 1370 1371 1372class autoupdate_EndToEndTest(test.test): 1373 """Complete update test between two Chrome OS releases. 1374 1375 Performs an end-to-end test of updating a ChromeOS device from one version 1376 to another. The test performs the following steps: 1377 1378 1. Stages the source (full) and target update payload on the central 1379 devserver. 1380 2. Spawns a private Omaha-like devserver instance, configured to return 1381 the target (update) payload URL in response for an update check. 1382 3. Reboots the DUT. 1383 4. Installs a source image on the DUT (if provided) and reboots to it. 1384 5. Triggers an update check at the DUT. 1385 6. Watches as the DUT obtains an update and applies it. 1386 7. Reboots and repeats steps 5-6, ensuring that the next update check 1387 shows the new image version. 1388 1389 Some notes on naming: 1390 devserver: Refers to a machine running the Chrome OS Update Devserver. 1391 autotest_devserver: An autotest wrapper to interact with a devserver. 1392 Can be used to stage artifacts to a devserver. While 1393 this can also be used to update a machine, we do not 1394 use it for that purpose in this test as we manage 1395 updates with out own devserver instances (see below). 1396 omaha_devserver: This test's wrapper of a devserver running for the 1397 purposes of emulating omaha. This test controls the 1398 lifetime of this devserver instance and is separate 1399 from the autotest lab's devserver's instances which are 1400 only used for staging and hosting artifacts (because they 1401 scale). These are run on the same machines as the actual 1402 autotest devservers which are used for staging but on 1403 different ports. 1404 *staged_url's: In this case staged refers to the fact that these items 1405 are available to be downloaded statically from these urls 1406 e.g. 'localhost:8080/static/my_file.gz'. These are usually 1407 given after staging an artifact using a autotest_devserver 1408 though they can be re-created given enough assumptions. 1409 *update_url's: Urls refering to the update RPC on a given omaha devserver. 1410 Since we always use an instantiated omaha devserver to run 1411 updates, these will always reference an existing instance 1412 of an omaha devserver that we just created for the purposes 1413 of updating. 1414 devserver_hostname: At the start of each test, we choose a devserver 1415 machine in the lab for the test. We use the devserver 1416 instance there (access by autotest_devserver) to stage 1417 artifacts. However, we also use the same host to start 1418 omaha devserver instances for updating machines with 1419 (that reference the staged paylaods on the autotest 1420 devserver instance). This hostname refers to that 1421 machine we are using (since it's always the same for 1422 both staging/omaha'ing). 1423 1424 """ 1425 version = 1 1426 1427 # Timeout periods, given in seconds. 1428 _WAIT_AFTER_SHUTDOWN_SECONDS = 10 1429 _WAIT_AFTER_UPDATE_SECONDS = 20 1430 _WAIT_FOR_USB_INSTALL_SECONDS = 4 * 60 1431 _WAIT_FOR_MP_RECOVERY_SECONDS = 8 * 60 1432 _WAIT_FOR_INITIAL_UPDATE_CHECK_SECONDS = 12 * 60 1433 # TODO(sosa): Investigate why this needs to be so long (this used to be 1434 # 120 and regressed). 1435 _WAIT_FOR_DOWNLOAD_STARTED_SECONDS = 4 * 60 1436 _WAIT_FOR_DOWNLOAD_COMPLETED_SECONDS = 10 * 60 1437 _WAIT_FOR_UPDATE_COMPLETED_SECONDS = 4 * 60 1438 _WAIT_FOR_UPDATE_CHECK_AFTER_REBOOT_SECONDS = 15 * 60 1439 _DEVSERVER_HOSTLOG_REQUEST_TIMEOUT_SECONDS = 30 1440 1441 # Logs and their whereabouts. 1442 _WHERE_UPDATE_LOG = ('update_engine log (in sysinfo or on the DUT, also ' 1443 'included in the test log)') 1444 _WHERE_OMAHA_LOG = 'Omaha-devserver log (included in the test log)' 1445 1446 1447 def initialize(self): 1448 """Sets up variables that will be used by test.""" 1449 self._host = None 1450 self._omaha_devserver = None 1451 self._source_image_installed = False 1452 1453 self._devserver_dir = global_config.global_config.get_config_value( 1454 'CROS', 'devserver_dir', default=None) 1455 if self._devserver_dir is None: 1456 raise error.TestError( 1457 'Path to devserver source tree not provided; please define ' 1458 'devserver_dir under [CROS] in your shadow_config.ini') 1459 1460 1461 def cleanup(self): 1462 """Kill the omaha devserver if it's still around.""" 1463 if self._omaha_devserver: 1464 self._omaha_devserver.stop_devserver() 1465 1466 self._omaha_devserver = None 1467 1468 1469 def _dump_update_engine_log(self, test_platform): 1470 """Dumps relevant AU error log.""" 1471 try: 1472 error_log = test_platform.get_update_log(80) 1473 logging.error('Dumping snippet of update_engine log:\n%s', 1474 snippet(error_log)) 1475 except Exception: 1476 # Mute any exceptions we get printing debug logs. 1477 pass 1478 1479 1480 def _report_perf_data(self, perf_data): 1481 """Reports performance and resource data. 1482 1483 Currently, performance attributes are expected to include 'rss_peak' 1484 (peak memory usage in bytes). 1485 1486 @param perf_data: A dictionary containing performance attributes. 1487 """ 1488 rss_peak = perf_data.get('rss_peak') 1489 if rss_peak: 1490 rss_peak_kib = rss_peak / 1024 1491 logging.info('Peak memory (RSS) usage on DUT: %d KiB', rss_peak_kib) 1492 self.output_perf_value(description='mem_usage_peak', 1493 value=int(rss_peak_kib), 1494 units='KiB', 1495 higher_is_better=False) 1496 else: 1497 logging.warning('No rss_peak key in JSON returned by ' 1498 'update_engine_performance_monitor.py') 1499 1500 1501 def _error_initial_check(self, expected, actual, mismatched_attrs): 1502 if 'version' in mismatched_attrs: 1503 err_msg = ('Initial update check was received but the reported ' 1504 'version is different from what was expected.') 1505 if self._source_image_installed: 1506 err_msg += (' The source payload we installed was probably ' 1507 'incorrect or corrupt.') 1508 else: 1509 err_msg += (' The DUT is probably not running the correct ' 1510 'source image.') 1511 return err_msg 1512 1513 return 'A test bug occurred; inspect the test log.' 1514 1515 1516 def _error_intermediate(self, expected, actual, mismatched_attrs, action, 1517 problem): 1518 if 'event_result' in mismatched_attrs: 1519 event_result = actual.get('event_result') 1520 reported = (('different than expected (%s)' % 1521 EVENT_RESULT_DICT[event_result]) 1522 if event_result else 'missing') 1523 return ('The updater reported result code is %s. This could be an ' 1524 'updater bug or a connectivity problem; check the %s. For ' 1525 'a detailed log of update events, check the %s.' % 1526 (reported, self._WHERE_UPDATE_LOG, self._WHERE_OMAHA_LOG)) 1527 if 'event_type' in mismatched_attrs: 1528 event_type = actual.get('event_type') 1529 reported = ('different (%s)' % EVENT_TYPE_DICT[event_type] 1530 if event_type else 'missing') 1531 return ('Expected the updater to %s (%s) but received event type ' 1532 'is %s. This could be an updater %s; check the ' 1533 '%s. For a detailed log of update events, check the %s.' % 1534 (action, EVENT_TYPE_DICT[expected['event_type']], reported, 1535 problem, self._WHERE_UPDATE_LOG, self._WHERE_OMAHA_LOG)) 1536 if 'version' in mismatched_attrs: 1537 return ('The updater reported an unexpected version despite ' 1538 'previously reporting the correct one. This is most likely ' 1539 'a bug in update engine; check the %s.' % 1540 self._WHERE_UPDATE_LOG) 1541 1542 return 'A test bug occurred; inspect the test log.' 1543 1544 1545 def _error_download_started(self, expected, actual, mismatched_attrs): 1546 return self._error_intermediate(expected, actual, mismatched_attrs, 1547 'begin downloading', 1548 'bug, crash or provisioning error') 1549 1550 1551 def _error_download_finished(self, expected, actual, mismatched_attrs): 1552 return self._error_intermediate(expected, actual, mismatched_attrs, 1553 'finish downloading', 'bug or crash') 1554 1555 1556 def _error_update_complete(self, expected, actual, mismatched_attrs): 1557 return self._error_intermediate(expected, actual, mismatched_attrs, 1558 'complete the update', 'bug or crash') 1559 1560 1561 def _error_reboot_after_update(self, expected, actual, mismatched_attrs): 1562 if 'event_result' in mismatched_attrs: 1563 event_result = actual.get('event_result') 1564 reported = ('different (%s)' % EVENT_RESULT_DICT[event_result] 1565 if event_result else 'missing') 1566 return ('The updater was expected to reboot (%s) but reported ' 1567 'result code is %s. This could be a failure to reboot, an ' 1568 'updater bug or a connectivity problem; check the %s and ' 1569 'the system log. For a detailed log of update events, ' 1570 'check the %s.' % 1571 (EVENT_RESULT_DICT[expected['event_result']], reported, 1572 self._WHERE_UPDATE_LOG, self._WHERE_OMAHA_LOG)) 1573 if 'event_type' in mismatched_attrs: 1574 event_type = actual.get('event_type') 1575 reported = ('different (%s)' % EVENT_TYPE_DICT[event_type] 1576 if event_type else 'missing') 1577 return ('Expected to successfully reboot into the new image (%s) ' 1578 'but received event type is %s. This probably means that ' 1579 'the new image failed to verify after reboot, possibly ' 1580 'because the payload is corrupt. This might also be an ' 1581 'updater bug or crash; check the %s. For a detailed log of ' 1582 'update events, check the %s.' % 1583 (EVENT_TYPE_DICT[expected['event_type']], reported, 1584 self._WHERE_UPDATE_LOG, self._WHERE_OMAHA_LOG)) 1585 if 'version' in mismatched_attrs: 1586 return ('The DUT rebooted after the update but reports a different ' 1587 'image version than the one expected. This probably means ' 1588 'that the payload we applied was incorrect or corrupt.') 1589 if 'previous_version' in mismatched_attrs: 1590 return ('The DUT rebooted after the update and reports the ' 1591 'expected version. However, it reports a previous version ' 1592 'that is different from the one previously reported. This ' 1593 'is most likely a bug in update engine; check the %s.' % 1594 self._WHERE_UPDATE_LOG) 1595 1596 return 'A test bug occurred; inspect the test log.' 1597 1598 1599 def _timeout_err(self, desc, timeout, event_type=None): 1600 if event_type is not None: 1601 desc += ' (%s)' % EVENT_TYPE_DICT[event_type] 1602 return ('Failed to receive %s within %d seconds. This could be a ' 1603 'problem with the updater or a connectivity issue. For more ' 1604 'details, check the %s.' % 1605 (desc, timeout, self._WHERE_UPDATE_LOG)) 1606 1607 1608 def run_update_test(self, test_platform, test_conf): 1609 """Runs the actual update test once preconditions are met. 1610 1611 @param test_platform: TestPlatform implementation. 1612 @param test_conf: A dictionary containing test configuration values 1613 1614 @raises ExpectedUpdateEventChainFailed if we failed to verify an update 1615 event. 1616 """ 1617 1618 # Record the active root partition. 1619 source_active_slot = test_platform.get_active_slot() 1620 logging.info('Source active slot: %s', source_active_slot) 1621 1622 source_release = test_conf['source_release'] 1623 target_release = test_conf['target_release'] 1624 1625 # Start the performance monitoring process on the DUT. 1626 test_platform.start_update_perf(self.bindir) 1627 try: 1628 # Trigger an update. 1629 test_platform.trigger_update(self._omaha_devserver) 1630 1631 # Track update progress. 1632 omaha_netloc = self._omaha_devserver.get_netloc() 1633 omaha_hostlog_url = urlparse.urlunsplit( 1634 ['http', omaha_netloc, '/api/hostlog', 1635 'ip=' + self._host.ip, '']) 1636 logging.info('Polling update progress from omaha/devserver: %s', 1637 omaha_hostlog_url) 1638 log_verifier = UpdateEventLogVerifier( 1639 omaha_hostlog_url, 1640 self._DEVSERVER_HOSTLOG_REQUEST_TIMEOUT_SECONDS) 1641 1642 # Verify chain of events in a successful update process. 1643 chain = ExpectedUpdateEventChain() 1644 chain.add_event( 1645 ExpectedUpdateEvent( 1646 version=source_release, 1647 on_error=self._error_initial_check), 1648 self._WAIT_FOR_INITIAL_UPDATE_CHECK_SECONDS, 1649 on_timeout=self._timeout_err( 1650 'an initial update check', 1651 self._WAIT_FOR_INITIAL_UPDATE_CHECK_SECONDS)) 1652 chain.add_event( 1653 ExpectedUpdateEvent( 1654 event_type=EVENT_TYPE_DOWNLOAD_STARTED, 1655 event_result=EVENT_RESULT_SUCCESS, 1656 version=source_release, 1657 on_error=self._error_download_started), 1658 self._WAIT_FOR_DOWNLOAD_STARTED_SECONDS, 1659 on_timeout=self._timeout_err( 1660 'a download started notification', 1661 self._WAIT_FOR_DOWNLOAD_STARTED_SECONDS, 1662 event_type=EVENT_TYPE_DOWNLOAD_STARTED)) 1663 chain.add_event( 1664 ExpectedUpdateEvent( 1665 event_type=EVENT_TYPE_DOWNLOAD_FINISHED, 1666 event_result=EVENT_RESULT_SUCCESS, 1667 version=source_release, 1668 on_error=self._error_download_finished), 1669 self._WAIT_FOR_DOWNLOAD_COMPLETED_SECONDS, 1670 on_timeout=self._timeout_err( 1671 'a download finished notification', 1672 self._WAIT_FOR_DOWNLOAD_COMPLETED_SECONDS, 1673 event_type=EVENT_TYPE_DOWNLOAD_FINISHED)) 1674 chain.add_event( 1675 ExpectedUpdateEvent( 1676 event_type=EVENT_TYPE_UPDATE_COMPLETE, 1677 event_result=EVENT_RESULT_SUCCESS, 1678 version=source_release, 1679 on_error=self._error_update_complete), 1680 self._WAIT_FOR_UPDATE_COMPLETED_SECONDS, 1681 on_timeout=self._timeout_err( 1682 'an update complete notification', 1683 self._WAIT_FOR_UPDATE_COMPLETED_SECONDS, 1684 event_type=EVENT_TYPE_UPDATE_COMPLETE)) 1685 1686 log_verifier.verify_expected_events_chain(chain) 1687 1688 # Wait after an update completion (safety margin). 1689 _wait(self._WAIT_AFTER_UPDATE_SECONDS, 'after update completion') 1690 finally: 1691 # Terminate perf monitoring process and collect its output. 1692 perf_data = test_platform.stop_update_perf() 1693 if perf_data: 1694 self._report_perf_data(perf_data) 1695 1696 # Only update the stateful partition (the test updated the rootfs). 1697 test_platform.finalize_update() 1698 1699 # Reboot the DUT after the update. 1700 test_platform.reboot_device() 1701 1702 # Trigger a second update check (again, test vs MP). 1703 test_platform.trigger_update(self._omaha_devserver) 1704 1705 # Observe post-reboot update check, which should indicate that the 1706 # image version has been updated. 1707 chain = ExpectedUpdateEventChain() 1708 expected_events = [ 1709 ExpectedUpdateEvent( 1710 event_type=EVENT_TYPE_UPDATE_COMPLETE, 1711 event_result=EVENT_RESULT_SUCCESS_REBOOT, 1712 version=target_release, 1713 previous_version=source_release, 1714 on_error=self._error_reboot_after_update), 1715 # Newer versions send a "rebooted_after_update" message after reboot 1716 # with the previous version instead of another "update_complete". 1717 ExpectedUpdateEvent( 1718 event_type=EVENT_TYPE_REBOOTED_AFTER_UPDATE, 1719 event_result=EVENT_RESULT_SUCCESS, 1720 version=target_release, 1721 previous_version=source_release, 1722 on_error=self._error_reboot_after_update), 1723 ] 1724 chain.add_event( 1725 expected_events, 1726 self._WAIT_FOR_UPDATE_CHECK_AFTER_REBOOT_SECONDS, 1727 on_timeout=self._timeout_err( 1728 'a successful reboot notification', 1729 self._WAIT_FOR_UPDATE_CHECK_AFTER_REBOOT_SECONDS, 1730 event_type=EVENT_TYPE_UPDATE_COMPLETE)) 1731 1732 log_verifier.verify_expected_events_chain(chain) 1733 1734 # Make sure we're using a different slot after the update. 1735 target_active_slot = test_platform.get_active_slot() 1736 if target_active_slot == source_active_slot: 1737 err_msg = 'The active image slot did not change after the update.' 1738 if None in (source_release, target_release): 1739 err_msg += (' The DUT likely rebooted into the old image, which ' 1740 'probably means that the payload we applied was ' 1741 'corrupt. But since we did not check the source ' 1742 'and/or target version we cannot say for sure.') 1743 elif source_release == target_release: 1744 err_msg += (' Given that the source and target versions are ' 1745 'identical, the DUT likely rebooted into the old ' 1746 'image. This probably means that the payload we ' 1747 'applied was corrupt.') 1748 else: 1749 err_msg += (' This is strange since the DUT reported the ' 1750 'correct target version. This is probably a system ' 1751 'bug; check the DUT system log.') 1752 raise error.TestFail(err_msg) 1753 1754 logging.info('Target active slot changed as expected: %s', 1755 target_active_slot) 1756 1757 logging.info('Update successful, test completed') 1758 1759 1760 # TODO(garnold) Remove the use_servo argument once control files on all 1761 # release branches have caught up. 1762 def run_once(self, host, test_conf, use_servo=False): 1763 """Performs a complete auto update test. 1764 1765 @param host: a host object representing the DUT 1766 @param test_conf: a dictionary containing test configuration values 1767 @param use_servo: DEPRECATED 1768 1769 @raise error.TestError if anything went wrong with setting up the test; 1770 error.TestFail if any part of the test has failed. 1771 1772 """ 1773 1774 self._host = host 1775 1776 # Find a devserver to use. We first try to pick a devserver with the 1777 # least load. In case all devservers' load are higher than threshold, 1778 # fall back to the old behavior by picking a devserver based on the 1779 # payload URI, with which ImageServer.resolve will return a random 1780 # devserver based on the hash of the URI. 1781 least_loaded_devserver = dev_server.get_least_loaded_devserver() 1782 if least_loaded_devserver: 1783 logging.debug('Choose the least loaded devserver: %s', 1784 least_loaded_devserver) 1785 autotest_devserver = dev_server.ImageServer(least_loaded_devserver) 1786 else: 1787 logging.warning('No devserver meets the maximum load requirement. ' 1788 'Pick a random devserver to use.') 1789 autotest_devserver = dev_server.ImageServer.resolve( 1790 test_conf['target_payload_uri']) 1791 devserver_hostname = urlparse.urlparse( 1792 autotest_devserver.url()).hostname 1793 counter_key = dev_server.ImageServer.create_stats_str( 1794 'paygen', devserver_hostname, artifacts=None) 1795 metadata = {'devserver': devserver_hostname, 1796 '_type': 'devserver_paygen'} 1797 metadata.update(test_conf) 1798 autotest_stats.Counter(counter_key, metadata=metadata).increment() 1799 1800 # Obtain a test platform implementation. 1801 test_platform = TestPlatform.create(host) 1802 test_platform.initialize(autotest_devserver, self._devserver_dir) 1803 1804 # Stage source images and update payloads onto a devserver. 1805 staged_urls = test_platform.prep_artifacts(test_conf) 1806 self._source_image_installed = bool(staged_urls.source_url) 1807 1808 # Prepare the DUT (install source version etc). 1809 test_platform.prep_device_for_update(test_conf['source_release']) 1810 1811 self._omaha_devserver = OmahaDevserver( 1812 devserver_hostname, self._devserver_dir, 1813 staged_urls.target_url) 1814 self._omaha_devserver.start_devserver() 1815 1816 try: 1817 self.run_update_test(test_platform, test_conf) 1818 except ExpectedUpdateEventChainFailed: 1819 self._dump_update_engine_log(test_platform) 1820 raise 1821 1822 test_platform.check_device_after_update(test_conf['target_release']) 1823