1# Copyright 2017 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.
4import json
5import logging
6import os
7import random
8import time
9
10from autotest_lib.client.common_lib import error
11from autotest_lib.client.common_lib import lsbrelease_utils
12from autotest_lib.server import autotest
13from autotest_lib.server.cros.update_engine import update_engine_test
14from chromite.lib import retry_util
15
16class autoupdate_ForcedOOBEUpdate(update_engine_test.UpdateEngineTest):
17    """Runs a forced autoupdate during OOBE."""
18    version = 1
19
20    # We override the default lsb-release file.
21    _CUSTOM_LSB_RELEASE = '/mnt/stateful_partition/etc/lsb-release'
22
23    # Version we tell the DUT it is on before update.
24    _CUSTOM_LSB_VERSION = '0.0.0.0'
25
26    # Expected hostlog events during update: 4 during rootfs
27    _ROOTFS_HOSTLOG_EVENTS = 4
28
29
30    def cleanup(self):
31        self._host.run('rm %s' % self._CUSTOM_LSB_RELEASE, ignore_status=True)
32
33        # Get the last two update_engine logs: before and after reboot.
34        files = self._host.run('ls -t -1 '
35                               '/var/log/update_engine/').stdout.splitlines()
36        for i in range(2):
37            self._host.get_file('/var/log/update_engine/%s' % files[i],
38                                self.resultsdir)
39        cmd = 'update_engine_client --update_over_cellular=no'
40        retry_util.RetryException(error.AutoservRunError, 2, self._host.run,
41                                  cmd)
42        super(autoupdate_ForcedOOBEUpdate, self).cleanup()
43
44    def _get_chromeos_version(self):
45        """Read the ChromeOS version from /etc/lsb-release."""
46        lsb = self._host.run('cat /etc/lsb-release').stdout
47        return lsbrelease_utils.get_chromeos_release_version(lsb)
48
49
50    def _create_hostlog_files(self):
51        """Create the two hostlog files for the update.
52
53        To ensure the update was succesful we need to compare the update
54        events against expected update events. There is a hostlog for the
55        rootfs update and for the post reboot update check.
56        """
57        hostlog = self._omaha_devserver.get_hostlog(self._host.ip,
58                                                    wait_for_reboot_events=True)
59        logging.info('Hostlog: %s', hostlog)
60
61        # File names to save the hostlog events to.
62        rootfs_hostlog = os.path.join(self.resultsdir, 'hostlog_rootfs')
63        reboot_hostlog = os.path.join(self.resultsdir, 'hostlog_reboot')
64
65        # Each time we reboot in the middle of an update we ping omaha again
66        # for each update event. So parse the list backwards to get the final
67        # events.
68        with open(reboot_hostlog, 'w') as outfile:
69            json.dump(hostlog[-1:], outfile)
70        with open(rootfs_hostlog, 'w') as outfile:
71            json.dump(hostlog[len(hostlog)-1-self._ROOTFS_HOSTLOG_EVENTS:-1],
72                      outfile)
73
74        return rootfs_hostlog, reboot_hostlog
75
76
77    def _get_update_percentage(self):
78        """Returns the current payload downloaded percentage."""
79        while True:
80            status = self._host.run('update_engine_client --status',
81                                    ignore_timeout=True,
82                                    timeout=10)
83            if not status:
84                continue
85            status = status.stdout.splitlines()
86            logging.debug(status)
87            if 'UPDATE_STATUS_IDLE' in status[2]:
88                raise error.TestFail('Update status was idle while trying to '
89                                     'get download status.')
90            # If we call this right after reboot it may not be downloading yet.
91            if 'UPDATE_STATUS_DOWNLOADING' not in status[2]:
92                time.sleep(1)
93                continue
94            return float(status[1].partition('=')[2])
95
96
97    def _update_continued_where_it_left_off(self, percentage):
98        """
99        Checks that the update did not restart after an interruption.
100
101        @param percentage: The percentage the last time we checked.
102
103        @returns True if update continued. False if update restarted.
104
105        """
106        completed = self._get_update_percentage()
107        logging.info('New value: %f, old value: %f', completed, percentage)
108        return completed >= percentage
109
110
111    def _wait_for_update_to_complete(self):
112        """Wait for the update that started to complete.
113
114        Repeated check status of update. It should move from DOWNLOADING to
115        FINALIZING to COMPLETE to IDLE.
116        """
117        while True:
118            status = self._host.run('update_engine_client --status',
119                                    ignore_timeout=True,
120                                    timeout=10)
121
122            # During reboot, status will be None
123            if status is not None:
124                status = status.stdout.splitlines()
125                logging.debug(status)
126                if 'UPDATE_STATUS_IDLE' in status[2]:
127                    break
128            time.sleep(1)
129
130
131    def _wait_for_percentage(self, percent):
132        """
133        Waits until we reach the percentage passed as the input.
134
135        @param percent: The percentage we want to wait for.
136        """
137        while True:
138            completed = self._get_update_percentage()
139            logging.debug('Checking if %s is greater than %s', completed,
140                          percent)
141            if completed > percent:
142                break
143            time.sleep(1)
144
145
146    def run_once(self, host, full_payload=True, cellular=False,
147                 interrupt=False, max_updates=1, job_repo_url=None):
148        """
149        Runs a forced autoupdate during ChromeOS OOBE.
150
151        @param host: The DUT that we are running on.
152        @param full_payload: True for a full payload. False for delta.
153        @param cellular: True to do the update over a cellualar connection.
154                         Requires that the DUT have a sim card slot.
155        @param interrupt: True to interrupt the update in the middle.
156        @param max_updates: Used to tell the test how many times it is
157                            expected to ping its omaha server.
158        @param job_repo_url: Used for debugging locally. This is used to figure
159                             out the current build and the devserver to use.
160                             The test will read this from a host argument
161                             when run in the lab.
162
163        """
164        self._host = host
165
166        # veyron_rialto is a medical device with a different OOBE that auto
167        # completes so this test is not valid on that device.
168        if 'veyron_rialto' in self._host.get_board():
169            raise error.TestNAError('Rialto has a custom OOBE. Skipping test.')
170
171        update_url = self.get_update_url_for_test(job_repo_url,
172                                                  full_payload=full_payload,
173                                                  critical_update=True,
174                                                  cellular=cellular,
175                                                  max_updates=max_updates)
176        logging.info('Update url: %s', update_url)
177        before = self._get_chromeos_version()
178        payload_info = None
179        if cellular:
180            cmd = 'update_engine_client --update_over_cellular=yes'
181            retry_util.RetryException(error.AutoservRunError, 2, self._host.run,
182                                      cmd)
183            # Get the payload's information (size, SHA256 etc) since we will be
184            # setting up our own omaha instance on the DUT. We pass this to
185            # the client test.
186            payload = self._get_payload_url(full_payload=full_payload)
187            staged_url = self._stage_payload_by_uri(payload)
188            payload_info = self._get_staged_file_info(staged_url)
189
190        # Call client test to start the forced OOBE update.
191        client_at = autotest.Autotest(self._host)
192        client_at.run_test('autoupdate_StartOOBEUpdate', image_url=update_url,
193                           cellular=cellular, payload_info=payload_info,
194                           full_payload=full_payload)
195
196        # Don't continue the test if the client failed for any reason.
197        client_at._check_client_test_result(self._host,
198                                            'autoupdate_StartOOBEUpdate')
199
200        if interrupt:
201            # Choose a random downloaded percentage to interrupt the update.
202            percent = random.uniform(0.1, 0.8)
203            logging.debug('Percent when we will interrupt: %f', percent)
204            self._wait_for_percentage(percent)
205            logging.info('We will start interrupting the update.')
206            completed = self._get_update_percentage()
207
208            # Reboot the DUT during the update.
209            self._host.reboot()
210            if not self._update_continued_where_it_left_off(completed):
211                raise error.TestFail('The update did not continue where it '
212                                     'left off before rebooting.')
213            completed = self._get_update_percentage()
214
215            # Disconnect and reconnect network.
216            reconnect_test_name = 'autoupdate_DisconnectReconnectNetwork'
217            client_at.run_test(reconnect_test_name, update_url=update_url)
218            client_at._check_client_test_result(self._host, reconnect_test_name)
219            if not self._update_continued_where_it_left_off(completed):
220                raise error.TestFail('The update did not continue where it '
221                                     'left off before disconnecting network.')
222
223            # Suspend / Resume
224            boot_id = self._host.get_boot_id()
225            self._host.servo.lid_close()
226            self._host.test_wait_for_sleep()
227            self._host.servo.lid_open()
228            self._host.test_wait_for_boot(boot_id)
229            if not self._update_continued_where_it_left_off(completed):
230                raise error.TestFail('The update did not continue where it '
231                                     'left off after suspend/resume.')
232
233        self._wait_for_update_to_complete()
234
235        if cellular:
236            # We didn't have a devserver so we cannot check the hostlog to
237            # ensure the update completed successfully. Instead we can check
238            # that the second-to-last update engine log has the successful
239            # update message. Second to last because its the one before OOBE
240            # rebooted.
241            update_engine_files_cmd = 'ls -t -1 /var/log/update_engine/'
242            files = self._host.run(update_engine_files_cmd).stdout.splitlines()
243            before_reboot_file = self._host.run('cat /var/log/update_engine/%s'
244                                                % files[1]).stdout
245            self._check_for_cellular_entries_in_update_log(before_reboot_file)
246
247            success = 'Update successfully applied, waiting to reboot.'
248            update_ec = self._host.run('cat /var/log/update_engine/%s | grep '
249                                       '"%s"' % (files[1], success)).exit_status
250            if update_ec != 0:
251                raise error.TestFail('We could not verify that the update '
252                                     'completed successfully. Check the logs.')
253            return
254
255        # Verify that the update completed successfully by checking hostlog.
256        rootfs_hostlog, reboot_hostlog = self._create_hostlog_files()
257        self.verify_update_events(self._CUSTOM_LSB_VERSION, rootfs_hostlog)
258        self.verify_update_events(self._CUSTOM_LSB_VERSION, reboot_hostlog,
259                                  self._CUSTOM_LSB_VERSION)
260
261        after = self._get_chromeos_version()
262        logging.info('Successfully force updated from %s to %s.', before, after)
263