# Copyright 2017 The ChromiumOS Authors
# Use of this source code is governed by a BSD-style license that can be
# found in the LICENSE file.

import logging
import pprint
import time
import re

from autotest_lib.client.common_lib import error
from autotest_lib.server import autotest
from autotest_lib.server.cros.faft.cr50_test import Cr50Test

class firmware_Cr50DeviceState(Cr50Test):
    """Verify Cr50 tracks the EC and AP state correctly.

    Put the device through S0, S0ix, S3, and G3. Cr50 responds to these state
    changes by enabling/disabling uart and changing its suspend type. Verify
    that none of these cause any interrupt storms on Cr50. Make sure that there
    aren't any interrupt storms and that Cr50 enters regular or deep sleep a
    reasonable amount of times.
    """
    version = 1

    # If the system boots, it should be in normal or dev mode. These are the
    # only valid pcr0 values.
    VALID_PCR0_VALUES = [
            # Normal Mode
            '89EAF35134B4B3C649F44C0C765B96AEAB8BB34EE83CC7A683C4E53D1581C8C7',
            # Dev Mode
            '23E14DD9BB51A50E16911F7E11DF1E1AAF0B17134DC739C5653607A1EC8DD37A',
    ]
    DEEP_SLEEP_STEP_SUFFIX = ' Num Deep Sleep Steps'
    BOARD_HAS_SBU_ISSUES = ['octopus']

    # Use negative numbers to keep track of counts not in the IRQ list. The
    # actual number don't matter too much. Just make sure deep sleep is the
    # lowest, so it's printed first.
    KEY_DEEP_SLEEP = -10
    KEY_TPM_INIT = -5
    KEY_CMD_END_TIME = -4
    KEY_COLD_RESET_TIME = -3
    KEY_TIME = -2
    KEY_RESET = -1

    IGNORED_KEYS = [KEY_CMD_END_TIME]
    # TPM initialization time doesn't relate to the previous boot. Don't look
    # at the difference between each step. Look at each value independently.
    STEP_INDEPENDENT_KEYS = [KEY_TPM_INIT]
    KEY_SURVIVES_DS = [KEY_DEEP_SLEEP, KEY_COLD_RESET_TIME]
    GSC_STATUS_DICT = {
            KEY_TPM_INIT: 'TPM init (us)',
            KEY_RESET: 'Reset Count',
            KEY_DEEP_SLEEP: 'Deep Sleep Count',
            KEY_TIME: 'Time (DS)',
            KEY_COLD_RESET_TIME: 'Time (cold reset)',
    }

    ENTER_STATE_WAIT = 15
    POWER_STATE_CHECK_TRIES = 6

    DEEP_SLEEP_MAX = 2
    ARM = 'ARM '
    # If there are over 100,000 interrupts, it is an interrupt storm.
    DEFAULT_COUNTS = [0, 100000]
    # A dictionary of ok count values for each irq that shouldn't follow the
    # DEFAULT_COUNTS range.
    EXPECTED_IRQ_COUNT_RANGE = {
            KEY_RESET: [0, 0],
            KEY_DEEP_SLEEP: [0, DEEP_SLEEP_MAX],
            'lid_close' + DEEP_SLEEP_STEP_SUFFIX: [0, 2],
            'default_suspend' + DEEP_SLEEP_STEP_SUFFIX: [0, 2],
            'S0ix' + DEEP_SLEEP_STEP_SUFFIX: [0, 0],
            # Cr50 may enter deep sleep an extra time, because of how the test
            # collects taskinfo counts. Just verify that it does enter deep sleep
            'S3' + DEEP_SLEEP_STEP_SUFFIX: [1, 2],
            'G3' + DEEP_SLEEP_STEP_SUFFIX: [1, 2],
            'S5' + DEEP_SLEEP_STEP_SUFFIX: [1, 2],
            # ARM devices don't enter deep sleep in S3
            ARM + 'S3' + DEEP_SLEEP_STEP_SUFFIX: [0, 0],
            ARM + 'G3' + DEEP_SLEEP_STEP_SUFFIX: [1, 2],
            ARM + 'S5' + DEEP_SLEEP_STEP_SUFFIX: [1, 2],
            ARM + 'lid_close' + DEEP_SLEEP_STEP_SUFFIX: [0, 2],
            ARM + 'default_suspend' + DEEP_SLEEP_STEP_SUFFIX: [0, 2],
            # Regular sleep is calculated based on the cr50 time
    }
    START = ''
    INCREASE = '+'
    DS_RESUME = 'DS'
    # Keys like tpm initialization time aren't related to the previous boot.
    # Don't look at the value from the previous step to determine anything.
    # Use ' ' since it has to be different from START.
    STEP_INDEPENDENT = ' '

    TMP_POWER_MANAGER_PATH = '/tmp/power_manager'
    POWER_MANAGER_PATH = '/var/lib/power_manager'
    MEM_SLEEP_PATH = '/sys/power/mem_sleep'
    MEM_SLEEP_S0IX = 'echo %s > %s ; sleep 1' % ('s2idle', MEM_SLEEP_PATH)
    MEM_SLEEP_S3 = 'echo %s > %s ; sleep 1' % ('deep', MEM_SLEEP_PATH)
    POWER_STATE_PATH = '/sys/power/state'
    POWER_STATE_S0IX = 'echo %s > %s' % ('freeze', POWER_STATE_PATH)
    POWER_STATE_S3 = 'echo %s > %s' % ('mem', POWER_STATE_PATH)
    MOUNT_POWERD = (
            'mkdir -p %s && echo 0 > %s/suspend_to_idle && mount --bind %s %s && restart powerd'
            % (TMP_POWER_MANAGER_PATH, TMP_POWER_MANAGER_PATH,
               TMP_POWER_MANAGER_PATH, POWER_MANAGER_PATH))


    # TODO(mruthven): remove ec chan restriction once soraka stops spamming host
    # command output. The extra activity makes it look like a interrupt storm on
    # the EC uart.
    CHAN_ALL = 0xffffffff
    CHAN_EVENTS = 0x20
    CHAN_ACPI = 0x400
    CHAN_HOSTCMD = 0x80
    CHAN_USBCHARGE = 0x200000
    CHAN_RESTRICTED = CHAN_ALL ^ (CHAN_EVENTS | CHAN_ACPI | CHAN_HOSTCMD
                                  | CHAN_USBCHARGE)


    def initialize(self,
                   host,
                   cmdline_args,
                   full_args,
                   fwmp=None,
                   pcr_extend=False,
                   default_suspend=True,
                   manual_suspend=True,
                   ccd_en=None):
        if not host.servo or host.servo.main_device_is_ccd():
            raise error.TestNAError(
                    "Test can't run with ccd. Run with servo micro or c2d2")

        super(firmware_Cr50DeviceState, self).initialize(host, cmdline_args,
                                                         full_args)
        # Don't bother if there is no Chrome EC or if EC hibernate doesn't work.
        if not self.check_ec_capability():
            raise error.TestNAError("Nothing needs to be tested on this device")

        self.fwmp = fwmp
        self.pcr_extend = pcr_extend
        self.default_suspend = default_suspend
        self.manual_suspend = manual_suspend
        self.test_ccd_en = ccd_en

        if self.faft_config.ec_forwards_short_pp_press and self.manual_suspend:
            logging.warning(
                    'manual suspend not supported with ec_forwards_short_pp_press'
            )
            self.manual_suspend = False

        # The time in seconds to wait in each state. Wait enough time for gsc
        # to settle into whatever state. Make sure it's significantly longer
        # than it takes for gsc to enable sleep. Wait long enough for gsc to
        # enter deep sleep twice, so the test can catch extra wakeups.
        self.sleep_time = (self.gsc.DEEP_SLEEP_DELAY * 2) + 10

        self.INT_NAME = self.gsc.IRQ_DICT.copy()
        self.INT_NAME.update(self.GSC_STATUS_DICT)
        self.KEY_REGULAR_SLEEP = [k for k,v in self.INT_NAME.items()
                                    if 'WAKEUP' in v][0]
        self.SLEEP_KEYS = [ self.KEY_REGULAR_SLEEP, self.KEY_DEEP_SLEEP ]

        self.deep_sleep_in_s0i3 = self.check_cr50_capability(
            ['deep_sleep_in_s0i3'])

        # If the TPM is reset in S0i3, the CR50 may enter deep sleep during S0i3.
        # Cr50 may enter deep sleep an extra time, because of how the test
        # collects taskinfo counts. So the range is set conservatively to 0-2.
        if self.deep_sleep_in_s0i3:
            irq_s0ix_deep_sleep_key = 'S0ix' + self.DEEP_SLEEP_STEP_SUFFIX
            self.EXPECTED_IRQ_COUNT_RANGE[irq_s0ix_deep_sleep_key] = [0, 2]
        # Set the maximum amount of time allowed for the gsc chip type or board type.
        max_tpm_init = (getattr(self.faft_config, 'custom_max_tpm_init_us',
                                None) or self.gsc.TPM_INIT_MAX)
        self.EXPECTED_IRQ_COUNT_RANGE[self.KEY_TPM_INIT] = [0, max_tpm_init]
        # Use the sleep time or the amount of time it takes for the dut to respond
        # to a ping after reboot.
        # Multiply sleep time by 2 in case it takes a long time for the device
        # to boot. It's supposed to be a conservative maximum.
        sleep_time = self.sleep_time * 2 + self.faft_config.delay_reboot_to_ping
        self.EXPECTED_IRQ_COUNT_RANGE[self.KEY_TIME] = [0, sleep_time]

    def get_tpm_init_time(self):
        """If the AP is on, return the time it took the tpm to initialize."""
        # The board may not support cbmem after suspend. Ignore errors on those
        # devices.
        ignore_status = not getattr(self.faft_config, 'suspend_cbmem', True)
        result = self.host.run('cbmem -t', ignore_status=ignore_status)
        if result.exit_status:
            return 0
        match = re.search('TPM initialization.*\((.*)\)', result.stdout)
        return int(match.group(1).replace(',', ''))

    def mount_power_config(self):
        """Mounts power_manager settings to tmp,
        ensuring that any changes do not persist across reboots
        """
        self.faft_client.system.run_shell_command(self.MOUNT_POWERD, True)

    def umount_power_config(self):
        """Unmounts power_manager settings"""
        self.faft_client.system.run_shell_command(
                'umount %s && restart powerd' % self.POWER_MANAGER_PATH, True)

    def set_suspend_to_idle(self, value):
        """Set suspend_to_idle by writing to power_manager settings"""
        # Suspend to idle expects 0/1 so %d is used
        self.faft_client.system.run_shell_command(
                'echo %d > %s/suspend_to_idle' %
                (value, self.TMP_POWER_MANAGER_PATH), True)

    def log_sleep_debug_information(self):
        """Log some information used for debugging sleep issues"""
        logging.debug(
            self.gsc.send_command_retry_get_output('sleepmask',
                                                    ['sleepmask.*>'],
                                                    safe=True)[0])
        logging.debug(
            self.gsc.send_command_retry_get_output('sysinfo',
                                                    ['sysinfo.*>'],
                                                    safe=True)[0])


    def get_irq_counts(self):
        """Return a dict with the irq numbers as keys and counts as values"""
        irq_counts = { self.KEY_REGULAR_SLEEP : 0 }
        # Running all of these commands may take a while. Track how much time
        # commands are running, so we can offset the cr50 time to set sleep
        # expectations
        start_cmd_time = int(self.gsc.gettime())
        irq_counts[self.KEY_TIME] = start_cmd_time
        irq_counts[self.
                   KEY_COLD_RESET_TIME] = self.gsc.gettime_since_cold_reset()

        irq_counts.update(self.gsc.get_irq_counts())

        irq_counts[self.KEY_RESET] = int(self.gsc.get_reset_count())
        irq_counts[self.KEY_DEEP_SLEEP] = int(self.gsc.get_deep_sleep_count())
        # Log some information, so we can debug issues with sleep.
        self.log_sleep_debug_information()
        # Track when the commands end, so the test can ignore the time spent
        # running these console commands.
        end_cmd_time = int(self.gsc.gettime())
        irq_counts[self.KEY_CMD_END_TIME] = end_cmd_time
        logging.info('Commands finished in %d seconds',
                     end_cmd_time - start_cmd_time)
        return irq_counts


    def get_expected_count(self, irq_key, cr50_time, idle, ds_resume):
        """Get the expected irq increase for the given irq and state

        Args:
            irq_key: the irq int
            cr50_time: the cr50 time in seconds
            idle: Cr50 should enter regular sleep while the device is idle.

        Returns:
            A list with the expected irq count range [min, max]
        """
        # CCD will prevent sleep
        if self.ccd_enabled and (irq_key in self.SLEEP_KEYS or
            self.DEEP_SLEEP_STEP_SUFFIX in str(irq_key)):
            # If the board has sbu issues, the device may enter sleep. Ignore
            # it until the hardware is fixed.
            if self.servo.get_board() in self.BOARD_HAS_SBU_ISSUES:
                return self.DEFAULT_COUNTS
            return [0, 0]
        if irq_key == self.KEY_REGULAR_SLEEP:
            # If cr50_time is really low, we probably woke cr50 up using
            # taskinfo, which would be a pmu wakeup.
            if cr50_time < 5:
                return [0, 1]
            # Only enforce the minimum regular sleep count if the device is
            # idle. Cr50 may not enter regular sleep during power state
            # transitions.
            if idle and cr50_time > self.gsc.DEEP_SLEEP_DELAY:
                if self.gsc.SLEEP_RATE == 0:
                    min_count = 1
                else:
                    min_count = cr50_time - self.gsc.DEEP_SLEEP_DELAY
            else:
                min_count = 0
            # Check that cr50 isn't continuously entering and exiting sleep.
            # The PMU wakeups should happen around twice a second. Depending
            # on TPM activity it may occur more often. Add 2 to the multiplier
            # to allow for extra wakeups. This is mostly to catch issues that
            # cause cr50 to wake up 100 times a second
            max_count = cr50_time * (self.gsc.SLEEP_RATE + 2)
            return [min_count, max_count]
        # If ccd is disabled, ccd irq counts should not increase.
        if not self.ccd_enabled and (irq_key in self.gsc.CCD_IRQS):
            return [0, 0]
        return self.EXPECTED_IRQ_COUNT_RANGE.get(irq_key, self.DEFAULT_COUNTS)


    def check_increase(self, irq_key, name, increase, expected_range):
        """Verify the irq count is within the expected range

        Args:
            irq_key: the irq int
            name: the irq name string
            increase: the irq count
            expected_range: A list with the valid irq count range [min, max]

        Returns:
            '' if increase is in the given range. If the increase isn't in the
            range, it returns an error message.
        """
        min_count, max_count = expected_range
        if min_count > increase or max_count < increase:
            err_msg = '%s %s: %s not in range %s' % (name, irq_key, increase,
                expected_range)
            return err_msg
        return ''


    def get_step_events(self):
        """Use the deep sleep counts to determine the step events"""
        ds_counts = self.get_irq_step_counts(self.KEY_DEEP_SLEEP)
        events = []
        for i, count in enumerate(ds_counts):
            if not i:
                events.append(self.START)
            elif count != ds_counts[i - 1]:
                # If the deep sleep count changed, Cr50 recovered deep sleep
                # and the irq counts are reset.
                events.append(self.DS_RESUME)
            else:
                events.append(self.INCREASE)
        return events


    def get_irq_step_counts(self, irq_key):
        """Get a list of the all of the step counts for the given irq"""
        return [ irq_dict.get(irq_key, 0) for irq_dict in self.steps ]


    def check_for_errors(self, state):
        """Check for unexpected IRQ counts at each step.

        Find the irq count errors and add them to run_errors.

        Args:
            state: The power state: S0, S0ix, S3, or G3.
        """
        num_steps = len(self.steps)
        # Get all of the deep sleep counts
        events = self.get_step_events()

        irq_list = list(self.irqs)
        irq_list.sort()

        # Pad the start of the step names, so the names align with each step
        # count.
        irq_diff = ['%24s|%s|' % ('', '|'.join(self.step_names))]
        step_errors = [ [] for i in range(num_steps) ]

        end_cmd_times = self.get_irq_step_counts(self.KEY_CMD_END_TIME)
        start_cmd_times = self.get_irq_step_counts(self.KEY_TIME)
        cr50_time_diff = []
        for i, start_time in enumerate(start_cmd_times):
            # The test collects a lot of information using console commands.
            # These take a long time to run and cr50 isn't idle. The idle
            # time is the time this step started minus the time the last set of
            # commands finished running.
            if events[i] == self.INCREASE:
                cr50_time_diff.append(start_time - end_cmd_times[i - 1])
            else:
                cr50_time_diff.append(start_time)

        # Go through each irq and update its info in the progress dict
        for irq_key in irq_list:
            if irq_key in self.IGNORED_KEYS:
                continue
            name = self.INT_NAME.get(irq_key, 'Unknown')
            # Print the IRQ name on the left of the column and the irq number
            # on the right.
            irq_progress_str = ['%-19s %3s' % (name, irq_key)]

            irq_counts = self.get_irq_step_counts(irq_key)
            for step, count in enumerate(irq_counts):
                event = events[step]

                # The deep sleep counts are not reset after deep sleep. Change
                # the event to INCREASE.
                if irq_key in self.KEY_SURVIVES_DS and event == self.DS_RESUME:
                    event = self.INCREASE

                if irq_key in self.STEP_INDEPENDENT_KEYS:
                    event = self.STEP_INDEPENDENT

                if event == self.INCREASE:
                    count -= irq_counts[step - 1]

                # Check that the count increase is within the expected value.
                if event != self.START:
                    step_name = self.step_names[step].strip()
                    # TODO(b/153891388): raise actual error once the servo
                    # character loss issue is fixed.
                    if count < 0:
                        raise error.TestNAError('%s test found negative %s '
                                                'count %r (likely due to servo '
                                                'dropping characters)' %
                                                (step, step_name, count))
                    expected_range = self.get_expected_count(irq_key,
                            cr50_time_diff[step], 'idle' in step_name,
                            event == self.DS_RESUME)

                    rv = self.check_increase(irq_key, name, count,
                            expected_range)
                    if rv:
                        logging.info('Unexpected count in %s test: %s %s',
                                     state, step_name, rv)
                        step_errors[step].append(rv)

                irq_progress_str.append(' %2s %8d' % (event, count))

            # Separate each step count with '|'. Add '|' to the start and end of
            # the line.
            irq_diff.append('|%s|' % '|'.join(irq_progress_str))

        errors = {}

        ds_key = self.ARM if self.is_arm else ''
        ds_key += state + self.DEEP_SLEEP_STEP_SUFFIX
        expected_range = self.get_expected_count(ds_key, 0, False, False)
        rv = self.check_increase(None, ds_key, events.count(self.DS_RESUME),
                expected_range)
        if rv:
            logging.info('Unexpected count for %s %s', state, rv)
            errors[ds_key] = rv
        for i, step_error in enumerate(step_errors):
            if step_error:
                logging.error('Step %d errors:\n%s', i,
                        pprint.pformat(step_error))
                step = '%s step %d %s' % (state, i, self.step_names[i].strip())
                errors[step] = step_error

        if self._found_state:
            state += ' (%s)' % self._found_state
        logging.info('DIFF %s IRQ Counts - fwmp %s:\n%s', state, self.fwmp,
                     '\n'.join(irq_diff))
        if errors:
            logging.info('ERRORS %s IRQ Counts:\n%s', state,
                    pprint.pformat(errors))
            self.run_errors.update(errors)


    def ap_is_on_after_power_button_press(self):
        """Returns True if the AP is on after pressing the power button"""
        logging.info('Pressing the power button to turn on the AP')
        self.servo.power_normal_press()
        # Give the AP some time to turn on
        time.sleep(self.gsc.SHORT_WAIT)
        return self.gsc.ap_is_on()


    def trigger_s0(self):
        """Press the power button so the DUT will wake up."""
        if self.ap_is_on_after_power_button_press():
            return
        # Try a second time to see if the AP comes up.
        if not self.ap_is_on_after_power_button_press():
            raise error.TestError('Could not wake the AP using power button '
                                  '%s' % self.try_to_get_ap_state())
        logging.warning('Had to press power button twice to wake the AP')


    def enter_state(self, state, from_state=''):
        """Get the command to enter the power state"""
        target_state = state
        if state == 'S0':
            if self.lid_closed:
                logging.info('Open lid')
                self.servo.set('lid_open', 'yes')
                self.lid_closed = False
            else:
                self.trigger_s0()
            # Suppress host command output, so it doesn't look like an interrupt
            # storm. Set it whenever the system enters S0 to ensure the setting
            # is restored if the EC enters hibernate.
            time.sleep(2)
            logging.info('Setting EC chan %x', self.CHAN_RESTRICTED)
            self.ec.send_command('chan 0x%x' % self.CHAN_RESTRICTED)
        else:
            if state == 'lid_close':
                self.lid_closed = True
                logging.info('Open lid')
                self.servo.set_nocheck('lid_open', 'no')
                # It's difficult to tell the target state. Just log what it is.
                target_state = None
            elif state == 'default_suspend':
                self.faft_client.system.run_shell_command(
                        'powerd_dbus_suspend', False)
                # It's difficult to tell the target state. Just log what it is.
                target_state = None
            elif state == 'S0ix':
                self.enter_suspend(state)
            elif state == 'S3':
                self.enter_suspend(state)
            elif state == 'G3':
                self.faft_client.system.run_shell_command('poweroff', True)

        time.sleep(self.ENTER_STATE_WAIT)
        # check state transition
        if target_state and not self.wait_power_state(
                state, self.POWER_STATE_CHECK_TRIES):
            self._record_uart_capture()
            from_state = 'from ' + from_state if from_state else ''
            raise error.TestFail(
                    'Platform failed to reach %s state %s. %s' %
                    (state, from_state, self.try_to_get_ap_state()))
        power_state = self.get_power_state()
        logging.info('%s: Entered %s', state, power_state)
        # If the target state is unknown, track it for logging.
        self._found_state = '' if target_state else power_state

    def enter_suspend(self, state):
        """Enter S0ix or S3"""
        # Different devices require different methods to enter S0ix or S3. The
        # ones that deep_sleep_in_s0i3 must use power_manager, but other devices
        # need to bypass power_manager. b/233898484
        if self.deep_sleep_in_s0i3:
            self.set_suspend_to_idle(state == 'S0ix')
            self.suspend()
        else:
            cmds = []
            if self.host.path_exists(self.MEM_SLEEP_PATH):
                if state == 'S0ix':
                    cmds.append(self.MEM_SLEEP_S0IX)
                else:
                    cmds.append(self.MEM_SLEEP_S3)
            if state == 'S0ix':
                cmds.append(self.POWER_STATE_S0IX)
            else:
                cmds.append(self.POWER_STATE_S3)
            cmds = '; '.join(cmds)
            logging.info('runing suspend commands %s', cmds)
            self.faft_client.system.run_shell_command(cmds, False)

    def stage_irq_add(self, name):
        """Add the current irq counts to the stored dictionary of irq info"""
        logging.info('%s:', name.strip())
        irq_dict = self.get_irq_counts()
        self.steps.append(irq_dict)
        self.step_names.append(name.center(12))
        self.irqs.update(irq_dict.keys())


    def reset_irq_counts(self):
        """Reset the test IRQ counts"""
        self.steps = []
        self.step_names = []
        self.irqs = set(self.GSC_STATUS_DICT.keys())


    def run_transition(self, state):
        """Enter the given power state and reenter s0

        Enter the power state and return to S0. Wait long enough to ensure cr50
        will enter sleep mode, so we can verify that as well.

        Args:
            state: the power state: S0ix, S3, or G3
        """
        self.reset_irq_counts()

        # Enter the given state
        self.enter_state(state)
        self.stage_irq_add('entered %s' % (self._found_state or state))

        logging.info('waiting %d seconds', self.sleep_time)
        time.sleep(self.sleep_time)
        # Nothing is really happening. Cr50 should basically be idle during
        # sleep_time.
        self.stage_irq_add('idle in %s' % (self._found_state or state))

        # If the AP is off, the system will resume through firmware and run
        # TPM init. Verify it doesn't take too long to initialize the TPM.
        self.check_tpm_init = not self.gsc.ap_is_on()
        logging.info('Check TPM init: %s',
                     'yes' if self.check_tpm_init else 'no')

        # Return to S0
        logging.info('entering S0 from %s', state)
        self.enter_state('S0', state)
        logging.info('entered S0 from %s', state)
        self.stage_irq_add('entered S0')

        logging.info('waiting %d seconds', self.sleep_time)
        time.sleep(self.sleep_time)

        self.stage_irq_add('idle in S0')

        # The DUT has already been up for 60 seconds. It should be pingable.
        if not self.ping_dut_with_eth_reset():
            raise error.TestFail('Unable to ping dut after %s resume %s '
                                 '(reset eth)' %
                                 (state, self.try_to_get_ap_state()))

        self.print_fwmp('%s resume' % state)

        # The AP has to be on and have cbmem support to get `cbmem -t`.
        if self.check_tpm_init and self.gsc.ap_is_on():
            self.steps[-1][self.KEY_TPM_INIT] = self.get_tpm_init_time()
            logging.info('Resume from %s tpm initialized in %dus', state,
                         self.steps[-1][self.KEY_TPM_INIT])

    def print_fwmp(self, desc, initialized=True, check_pcr=True):
        """Print FWMP and PCR0 state for debugging."""
        result = self.run_fwmp_cmd(
                '--action=get_firmware_management_parameters',
                ignore_status=True)
        logging.info('FWMP %r exp(%s) act: %s', desc, self.fwmp,
                     result.stdout if result else None)
        if result.exit_status and self.fwmp and initialized:
            raise error.TestFail('Error getting FWMP: %r' % result)
        result = self.host.run('trunks_client --read_pcr --index=0')
        self._record_uart_capture()
        if not result:
            return
        pcr = result.stdout.split(':')[-1].strip()
        logging.info('PCR %r: %r', desc, pcr)
        if check_pcr and pcr not in self.VALID_PCR0_VALUES:
            raise error.TestFail('%s: invalid pcr0 value. %s not found in %r' %
                                 (desc, pcr, self.VALID_PCR0_VALUES))

    def verify_state(self, state):
        """Verify cr50 behavior while running through the power state"""

        try:
            self.run_transition(state)
        finally:
            # reset the system to S0 no matter what happens
            self.trigger_s0()
            # Reenable EC chan output.
            time.sleep(2)
            logging.info('Setting EC chan %x', self.CHAN_ALL)
            self.ec.send_command('chan 0x%x' % self.CHAN_ALL)

        # Check that the progress of the irq counts seems reasonable
        self.check_for_errors(state)

    def verify_sleep_state(self, state):
        """Verify cr50 behavior while running through S0ix or S3"""

        boot_id = self.host.get_boot_id()
        self.mount_power_config()
        self.verify_state(state)

        # umount_power_config will fail if the DUT reboots after
        # mount_power_config is called. Detect reboots and raise a clear error
        # message when one occurs.
        if boot_id == self.host.get_boot_id():
            self.umount_power_config()
        else:
            raise error.TestFail('DUT rebooted during %s test' % state)

    def is_arm_family(self):
        """Returns True if the DUT is an ARM device."""
        arch = self.host.run('arch').stdout.strip()
        return arch in ['aarch64', 'armv7l']


    def run_through_power_states(self):
        """Go through S0ix, S3, and G3. Verify there are no interrupt storms"""
        self._try_to_bring_dut_up()
        self.run_errors = {}
        self.ccd_str = 'ccd ' + ('enabled' if self.ccd_enabled else 'disabled')
        logging.info('Running through states with %s and fwmp(%s)',
                     self.ccd_str, self.fwmp)

        self.gsc.get_ccdstate()
        if not self.gsc.get_sleepmask() and self.ccd_enabled:
            logging.info('Sleepmask is not keeping cr50 up with ccd enabled')
            self.all_errors[self.ccd_str] = 'usb is not active with ccd enabled'
            return

        self.print_fwmp('start %s' % self.ccd_str)

        # Enter G3 first. All boards support it and tpm initialization will take
        # place. Entering G3 first ensures the tpm initialization data will be
        # from this test run.
        self.verify_state('G3')

        if self.default_suspend:
            self.verify_state('default_suspend')

            if self.check_ec_capability(["lid"]):
                try:
                    self.verify_state('lid_close')
                finally:
                    # Make sure it ends with the lid open.
                    self.servo.set('lid_open', 'yes')

        # Manually enter the non-default power states.
        if self.manual_suspend:
            try:
                if self.s0ix_supported:
                    self.verify_sleep_state('S0ix')

                    if self.s3_supported:
                        # Entering S3 after S0ix might not work. Reboot the DUT
                        # for S3 test.
                        logging.info('Rebooting for S3 test')
                        self.host.reboot()

                if self.s3_supported:
                    self.verify_sleep_state('S3')
            except Exception as e:
                self._try_to_bring_dut_up()
                logging.info('Caught exception %r', e)
                self.run_errors['Caught Exception'] = str(e)

        if self.run_errors:
            self.all_errors[self.ccd_str] = self.run_errors


    def init_fwmp(self):
        """Create the FWMP."""
        self.fast_ccd_open(True)
        self.gsc.set_ccd_level('lock')
        self.clear_tpm_owner_and_fwmp()

        self.print_fwmp('cleared tpm owner. Not initialized.',
                        initialized=False)
        client_at = autotest.Autotest(self.host)
        if self.fwmp:
            logging.info('Setting FWMP flags to %s', self.fwmp)
            client_at.run_test('firmware_SetFWMP',
                               flags=self.fwmp,
                               fwmp_cleared=True,
                               check_client_result=True)
        else:
            client_at.run_test('login_LoginSuccess')

        self.print_fwmp('init')

    def cleanup(self):
        """Clear the fwmp."""
        try:
            self._try_to_bring_dut_up()
            self.clear_tpm_owner_and_fwmp()
            self.gsc.ccd_reset_and_wipe_tpm()
        finally:
            super(firmware_Cr50DeviceState, self).cleanup()

    def is_s3_supported(self):
        """
        The S3 detection method changes depending on the kernel version.
        Newer kernels have a '/sys/power/mem_sleep' file that can be queried.
        If 'deep' exists within the 'mem_sleep', then S3 is supported.
        Older kernels do not have this file. Instead, one must look for 'mem'
        in '/sys/power/state'.
        See '{kernel-root}/Documentation/ABI/testing/sysfs-power' for more
        information.
        """
        supported = False
        if self.host.path_exists(self.MEM_SLEEP_PATH):
            supported = not self.host.run(f'grep -q deep '
                                          f'{self.MEM_SLEEP_PATH}',
                                          ignore_status=True).exit_status
        else:
            # Assumes kernel cli pararm: relative_sleep_states==0
            supported = not self.host.run(f'grep -q mem '
                                          f'{self.POWER_STATE_PATH}',
                                          ignore_status=True).exit_status
        return supported

    def run_once(self, host):
        """Go through S0ix, S3, and G3. Verify there are no interrupt storms"""

        self.all_errors = {}
        self.host = host
        self.lid_closed = False
        self.is_arm = self.is_arm_family()
        supports_dts_control = self.gsc.servo_dts_mode_is_valid()

        if supports_dts_control:
            if self.test_ccd_en:
                logging.info('Enable CCD for test')
                self.gsc.ccd_enable(raise_error=True)
            else:
                logging.info('Disable CCD for test')
                self.gsc.ccd_disable(raise_error=True)

        self.ccd_enabled = self.gsc.ccd_is_enabled()

        # If a ccd state was requested and the ccd state doesn't match, fail
        # with test na.
        if self.test_ccd_en != None and self.test_ccd_en != self.ccd_enabled:
            raise error.TestNAError('Setup does not support dts mode. Cannot '
                                    'verify state with ccd %sabled' %
                                    ('en' if self.test_ccd_en else 'dis'))
        # Check if the device supports S0ix.
        self.s0ix_supported = not self.host.run(
                'check_powerd_config --suspend_to_idle',
                ignore_status=True).exit_status
        # Check the faft config to see if it overrides the command check.
        skip_s0ix = getattr(self.faft_config, 's0ix_override_to_unsupported',
                            False)
        if skip_s0ix and self.s0ix_supported:
            logging.info('S0ix faft_config override')
            self.s0ix_supported = False
        logging.info('arm: %s', 'yes' if self.is_arm else 'no')
        logging.info('dts: %ssupported', '' if supports_dts_control else 'un')
        logging.info('ccd: %sabled', 'en' if self.ccd_enabled else 'dis')
        logging.info('S0ix: %s', self.s0ix_supported)
        # Check if the device supports S3.
        self.s3_supported = self.is_s3_supported()
        # Check the faft config to see if it overrides the command check.
        skip_s3 = getattr(self.faft_config, 's3_override_to_unsupported', False)
        if skip_s3 and self.s3_supported:
            logging.info('S3 faft_config override')
            self.s3_supported = False
        logging.info('S3: %s', self.s3_supported)

        if (not self.default_suspend and not self.s3_supported and
            not self.s0ix_supported):
            raise error.TestNAError('Manual suspend is unsupported.')

        if self.pcr_extend:
            self.fast_ccd_open(True)
            # Extend pcr0. The index must be 0. The value doesn't matter.
            self.host.run('trunks_client --extend_pcr --index=0 --value=7')
            # Manually send TPM2_Shutdown(STATE) to ensure saving the PCR0
            # value in nvmem
            self.host.run(
                    'trunks_send --raw 80 01 00 00 00 0c 00 00 01 45 00 01')
            self.print_fwmp('Extended PCR0',
                            initialized=False,
                            check_pcr=False)
            self.host.reboot()
            self.print_fwmp('PCR0 after reboot', initialized=False)
        self.init_fwmp()

        # The sleep times should be sufficient. Don't wait 3 minutes for
        # commands to timeout.
        self.host.set_default_run_timeout(60)
        self.run_through_power_states()

        self.trigger_s0()
        if self.all_errors:
            raise error.TestFail('Unexpected Device State (fwmp %r): %s' %
                                 (self.fwmp, self.all_errors))