Home | History | Annotate | Download | only in autoupdate_EndToEndTest
      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 
      5 import collections
      6 import json
      7 import logging
      8 import os
      9 import socket
     10 import time
     11 import urllib2
     12 import urlparse
     13 
     14 from autotest_lib.client.bin import utils as client_utils
     15 from autotest_lib.client.common_lib import error, global_config
     16 from autotest_lib.client.common_lib.cros import autoupdater, dev_server
     17 from autotest_lib.client.common_lib.cros.graphite import autotest_stats
     18 from autotest_lib.server import autotest, hosts, test
     19 from autotest_lib.server.cros.dynamic_suite import tools
     20 
     21 
     22 def _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 
     31 class ExpectedUpdateEventChainFailed(error.TestFail):
     32     """Raised if we fail to receive an expected event in a chain."""
     33 
     34 class RequiredArgumentMissing(error.TestError):
     35     """Raised if the test is missing a required argument."""
     36 
     37 
     38 # Update event types.
     39 EVENT_TYPE_DOWNLOAD_COMPLETE = '1'
     40 EVENT_TYPE_INSTALL_COMPLETE = '2'
     41 EVENT_TYPE_UPDATE_COMPLETE = '3'
     42 EVENT_TYPE_DOWNLOAD_STARTED = '13'
     43 EVENT_TYPE_DOWNLOAD_FINISHED = '14'
     44 EVENT_TYPE_REBOOTED_AFTER_UPDATE = '54'
     45 
     46 # Update event results.
     47 EVENT_RESULT_ERROR = '0'
     48 EVENT_RESULT_SUCCESS = '1'
     49 EVENT_RESULT_SUCCESS_REBOOT = '2'
     50 EVENT_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.
     54 EVENT_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 
     63 EVENT_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 
     71 def 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 
     85 class 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 
    223 class 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 
    318 class 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 
    379 class OmahaDevserverFailedToStart(error.TestError):
    380     """Raised when a omaha devserver fails to start."""
    381 
    382 
    383 class 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 
    680 class 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 
    815 class 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 
   1187 class 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 
   1372 class 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