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