• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
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.
4
5from __future__ import print_function
6
7import difflib
8import logging
9import math
10import time
11
12from autotest_lib.client.common_lib import error
13from autotest_lib.client.common_lib.cros import cr50_utils, tpm_utils
14from autotest_lib.server import autotest
15from autotest_lib.server.cros.faft.firmware_test import FirmwareTest
16
17
18class firmware_Cr50DeepSleepStress(FirmwareTest):
19    """Verify cr50 deep sleep after running power_SuspendStress.
20
21    Cr50 should enter deep sleep every suspend. Verify that by checking the
22    idle deep sleep count.
23
24    @param suspend_count: The number of times to reboot or suspend the device.
25    @param reset_type: a str with the cycle type: 'mem' or 'reboot'
26    """
27    version = 1
28
29    SLEEP_DELAY = 20
30    MIN_RESUME = 15
31    MIN_SUSPEND = 15
32    MEM = 'mem'
33    # Initialize the FWMP with a non-zero value. Use 100, because it's an
34    # unused flag and it wont do anything like lock out dev mode or ccd.
35    FWMP_FLAGS = '0x100'
36    # The deep sleep count may not exactly match the suspend count. This is the
37    # ratio of difference the test tolerates. If the difference/total suspend
38    # count is greater than this ratio, fail the test.
39    TOLERATED_ERROR = 0.05
40
41    def initialize(self, host, cmdline_args, suspend_count, reset_type):
42        """Make sure the test is running with access to the cr50 console"""
43        self.host = host
44        super(firmware_Cr50DeepSleepStress, self).initialize(host, cmdline_args)
45        if not hasattr(self, 'cr50'):
46            raise error.TestNAError('Test can only be run on devices with '
47                                    'access to the Cr50 console')
48
49        if self.servo.main_device_is_ccd():
50            raise error.TestNAError('deep sleep tests can only be run with a '
51                                    'servo flex')
52
53        # Reset the device
54        self.host.reset_via_servo()
55
56        # Save the original version, so we can make sure cr50 doesn't rollback.
57        self.original_cr50_version = self.cr50.get_active_version_info()
58        self._suspend_diff = 0
59
60
61    def cleanup(self):
62        """Clear the fwmp."""
63        try:
64            self.clear_fwmp()
65        finally:
66            super(firmware_Cr50DeepSleepStress, self).cleanup()
67
68
69    def create_fwmp(self):
70        """Create the FWMP."""
71        self.clear_fwmp()
72
73        # Clear the TPM owner, so we can set the fwmp.
74        tpm_utils.ClearTPMOwnerRequest(self.host, wait_for_ready=True)
75
76        logging.info('Setting FWMP flags to %s', self.FWMP_FLAGS)
77        autotest.Autotest(self.host).run_test('firmware_SetFWMP',
78                flags=self.FWMP_FLAGS, fwmp_cleared=True,
79                check_client_result=True)
80
81        if self.fwmp_is_cleared():
82            raise error.TestError('Unable to create the FWMP')
83
84
85    def check_fwmp(self):
86        """Returns an error message if the fwmp doesn't exist."""
87        if self.fwmp_is_cleared():
88            return 'FWMP was lost during test'
89        logging.info('No issues detected with the FWMP')
90
91
92    def check_cr50_version(self, expected_ver):
93        """Return an error message if the version changed running the test."""
94        version = self.cr50.get_active_version_info()
95        logging.info('running %s', version)
96
97        if version != expected_ver:
98            return 'version changed from %s to %s' % (expected_ver, version)
99
100
101    def run_reboots(self, suspend_count):
102        """Reboot the device the requested number of times
103
104        @param suspend_count: the number of times to reboot the device.
105        """
106        cr50_dev_mode = self.cr50.in_dev_mode()
107        # Disable CCD so Cr50 can enter deep sleep
108        self.cr50.ccd_disable()
109        self.cr50.clear_deep_sleep_count()
110        rv = self.check_cr50_deep_sleep(0)
111        if rv:
112            raise error.TestError('Issue setting up test %s' % rv)
113        errors = []
114
115        for i in range(suspend_count):
116            if not self._dut_is_responsive():
117                raise error.TestFail('Unable to ssh into DUT after %d resets' %
118                                     i)
119            self.host.run('ls /dev/tpm0')
120            # Power off the device
121            self.set_ap_off_power_mode('shutdown')
122
123            time.sleep(self.MIN_SUSPEND)
124
125            # Power on the device
126            self.servo.power_short_press()
127            time.sleep(self.MIN_RESUME)
128
129            rv = self.check_cr50_deep_sleep(i + 1)
130            if rv:
131                errors.append(rv)
132            # Make sure the device didn't boot into a different mode.
133            if self.cr50.in_dev_mode() != cr50_dev_mode:
134                errors.append('Switched out of %s mode' %
135                              ('dev' if cr50_dev_mode else 'normal'))
136            if errors:
137                msg = 'Reboot %d failed (%s)' % (i, ' and '.join(errors))
138                raise error.TestFail(msg)
139
140
141    def _dut_is_responsive(self):
142        """Returns True if the DUT eventually responds"""
143        return self.host.ping_wait_up(180)
144
145
146    def wait_for_client_after_changing_ccd(self, enable):
147        """Change CCD and wait for client.
148
149        @param enable: True to enable ccd. False to disable it.
150        @returns an error message
151        """
152        if enable:
153            self.cr50.ccd_enable()
154        else:
155            self.cr50.ccd_disable()
156        # power suspend stress needs to ssh into the DUT. If ethernet goes
157        # down, raise a test error, so we can tell the difference between
158        # dts ethernet issues and the dut going down during the suspend stress.
159        if self._dut_is_responsive():
160            return
161        msg = 'DUT is not pingable after %sabling ccd' % ('en' if enable else
162                                                          'dis')
163        logging.info(msg)
164
165        # TODO(b/135147658): Raise an error once CCD disable is fixed.
166        logging.info('Resetting DUT')
167        self.host.reset_via_servo()
168        if not self._dut_is_responsive():
169            return msg
170
171
172    def run_suspend_resume(self, suspend_count):
173        """Suspend the device the requested number of times
174
175        @param suspend_count: the number of times to suspend the device.
176        """
177        # Disable CCD so Cr50 can enter deep sleep
178        rv = self.wait_for_client_after_changing_ccd(False)
179        if rv:
180            raise error.TestFail('Network connection issue %s' % rv)
181        self.cr50.clear_deep_sleep_count()
182        rv = self.check_cr50_deep_sleep(0)
183        if rv:
184            raise error.TestError('Issue setting up test %s' % rv)
185        client_at = autotest.Autotest(self.host)
186        # Duration is set to 0, because it is required but unused when
187        # iterations is given.
188        client_at.run_test('power_SuspendStress', tag='idle',
189                           duration=0,
190                           min_suspend=self.MIN_SUSPEND,
191                           min_resume=self.MIN_RESUME,
192                           check_connection=False,
193                           suspend_iterations=suspend_count,
194                           suspend_state=self.MEM,
195                           check_client_result=True)
196
197
198    def check_cr50_deep_sleep(self, suspend_count):
199        """Verify cr50 has entered deep sleep the correct number of times.
200
201        Also print ccdstate and sleepmask output to get some basic information
202        about the cr50 state.
203        - sleepmask will show what may be preventing cr50 from entering sleep.
204        - ccdstate will show what cr50 thinks the AP state is. If the AP is 'on'
205          cr50 won't enter deep sleep.
206        All of these functions log the state, so no need to log the return
207        values.
208
209        @param suspend_count: The number of suspends.
210        @returns a message describing errors found in the state
211        """
212        exp_count = suspend_count if self._enters_deep_sleep else 0
213        act_count = self.cr50.get_deep_sleep_count()
214        logging.info('suspend %d: deep sleep count exp %d got %d',
215                     suspend_count, exp_count, act_count)
216
217        # Cr50 sometimes misses a suspend. Don't fail if the mismatch is within
218        # the tolerated difference.
219        tolerated_diff = math.ceil(exp_count * self.TOLERATED_ERROR)
220        act_diff = exp_count - act_count
221        logging.debug('suspend %d: tolerated diff %d got %d', suspend_count,
222                      tolerated_diff, act_diff)
223        if act_diff != self._suspend_diff:
224            logging.warning('suspend %d: mismatch changed from %d to %d',
225                            suspend_count, self._suspend_diff, act_diff)
226            self._suspend_diff = act_diff
227
228        self.cr50.get_sleepmask()
229        self.cr50.get_ccdstate()
230        hibernate = self.cr50.was_reset('RESET_FLAG_HIBERNATE')
231
232        errors = []
233        if exp_count and not hibernate:
234            errors.append('reset during suspend')
235
236        # Use the absolute value, because cr50 shouldn't suspend more or less
237        # than expected.
238        if abs(act_diff) > tolerated_diff:
239            errors.append('count mismatch expected %d got %d' % (exp_count,
240                                                                 act_count))
241        return ', '.join(errors) if errors else None
242
243
244    def check_flog_output(self, original_flog):
245        """Check for new flog messages.
246
247        @param original_flog: the original flog output.
248        @returns an error message with the flog difference, if there are new
249                 entries.
250        """
251        new_flog = cr50_utils.DumpFlog(self.host).strip()
252        logging.info('New FLOG output:\n%s', new_flog)
253        diff = difflib.unified_diff(original_flog.splitlines(),
254                                    new_flog.splitlines())
255        line_diff = '\n'.join(diff)
256        if line_diff:
257            logging.info('FLOG output:\n%s', line_diff)
258            return 'New Flog messages (%s)' % ','.join(diff)
259        else:
260            logging.info('No new FLOG output')
261
262
263    def run_once(self, host, suspend_count, reset_type):
264        """Verify deep sleep after suspending for the given number of cycles
265
266        The test either suspends to s3 or reboots the device depending on
267        reset_type. There are two valid reset types: mem and reboot. The test
268        will make sure that the device is off or in s3 long enough to ensure
269        Cr50 should be able to enter deep sleep. At the end of the test, it
270        checks that Cr50 entered deep sleep the same number of times it
271        suspended.
272
273        @param host: the host object representing the DUT.
274        @param suspend_count: The number of cycles to suspend or reboot the
275                device.
276        @param reset_type: a str with the cycle type: 'mem' or 'reboot'
277        """
278        if reset_type not in ['reboot', 'mem']:
279            raise error.TestNAError('Invalid reset_type. Use "mem" or "reboot"')
280        if self.MIN_SUSPEND + self.MIN_RESUME < self.SLEEP_DELAY:
281            logging.info('Minimum suspend-resume cycle is %ds. This is '
282                         'shorter than the Cr50 idle timeout. Cr50 may not '
283                         'enter deep sleep every cycle',
284                         self.MIN_SUSPEND + self.MIN_RESUME)
285        if not suspend_count:
286            raise error.TestFail('Need to provide non-zero suspend_count')
287        original_flog = cr50_utils.DumpFlog(self.host).strip()
288        logging.debug('Initial FLOG output:\n%s', original_flog)
289
290        # x86 devices should suspend once per reset. ARM will only suspend
291        # if the device enters s5.
292        if reset_type == 'reboot':
293            self._enters_deep_sleep = True
294        else:
295            is_arm = self.check_ec_capability(['arm'], suppress_warning=True)
296            self._enters_deep_sleep = not is_arm
297
298        self.create_fwmp()
299
300        main_error = None
301        try:
302            if reset_type == 'reboot':
303                self.run_reboots(suspend_count)
304            elif reset_type == 'mem':
305                self.run_suspend_resume(suspend_count)
306        except Exception as e:
307            main_error = e
308
309        errors = []
310        # Collect logs for debugging
311        # Autotest has some stages in between run_once and cleanup that may
312        # be run if the test succeeds. Do this here to make sure this is
313        # always run immediately after the suspend/resume cycles.
314        self.cr50.dump_nvmem()
315        # Reenable CCD. Reestablish network connection.
316        rv = self.wait_for_client_after_changing_ccd(True)
317        if rv:
318            errors.append(rv)
319        rv = self.check_flog_output(original_flog)
320        if rv:
321            errors.append(rv)
322        rv = self.check_fwmp()
323        if rv:
324            errors.append(rv)
325        rv = self.check_cr50_deep_sleep(suspend_count)
326        if rv:
327            errors.append(rv)
328        rv = self.check_cr50_version(self.original_cr50_version)
329        if rv:
330            errors.append(rv)
331        secondary_error = 'Suspend issues: %s' % ', '.join(errors)
332        if main_error:
333            logging.info(secondary_error)
334            raise main_error
335        if errors:
336            raise error.TestFail(secondary_error)
337