1# Copyright 2014 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
5import logging, re, time
6
7from autotest_lib.client.common_lib import error
8from autotest_lib.server.cros import vboot_constants as vboot
9from autotest_lib.server.cros.faft.firmware_test import FirmwareTest
10from autotest_lib.server.cros.watchdog_tester import WatchdogTester
11
12POWER_DIR = '/var/lib/power_manager'
13TMP_POWER_DIR = '/tmp/power_manager'
14
15class firmware_EventLog(FirmwareTest):
16    """
17    Test to ensure eventlog is written on boot and suspend/resume.
18    """
19    version = 1
20
21    _TIME_FORMAT = '%Y-%m-%d %H:%M:%S'
22
23    def initialize(self, host, cmdline_args):
24        super(firmware_EventLog, self).initialize(host, cmdline_args)
25        self.host = host
26        self.switcher.setup_mode('normal')
27        self.setup_usbkey(usbkey=True, host=False)
28
29    def _has_event(self, pattern):
30        return bool(filter(re.compile(pattern).search, self._events))
31
32    def _gather_events(self):
33        entries = self.faft_client.system.run_shell_command_get_output(
34                'mosys eventlog list')
35        now = self._now()
36        self._events = []
37        for line in reversed(entries):
38            _, time_string, event = line.split(' | ', 2)
39            timestamp = time.strptime(time_string, self._TIME_FORMAT)
40            if timestamp > now:
41                logging.error('Found prophecy: "%s"', line)
42                raise error.TestFail('Event timestamp lies in the future')
43            if timestamp < self._cutoff_time:
44                logging.debug('Event "%s" too early, stopping search', line)
45                break
46            logging.info('Found event: "%s"', line)
47            self._events.append(event)
48
49    # This assumes that Linux and the firmware use the same RTC. mosys converts
50    # timestamps to localtime, and so do we (by calling date without --utc).
51    def _now(self):
52        time_string = self.faft_client.system.run_shell_command_get_output(
53                'date +"%s"' % self._TIME_FORMAT)[0]
54        logging.debug('Current local system time on DUT is "%s"', time_string)
55        return time.strptime(time_string, self._TIME_FORMAT)
56
57    def disable_suspend_to_idle(self):
58        """Disable the powerd preference for suspend_to_idle."""
59        logging.info('Disabling suspend_to_idle')
60        # Make temporary directory to hold powerd preferences so we
61        # do not leave behind any state if the test is aborted.
62        self.host.run('mkdir -p %s' % TMP_POWER_DIR)
63        self.host.run('echo 0 > %s/suspend_to_idle' % TMP_POWER_DIR)
64        self.host.run('mount --bind %s %s' % (TMP_POWER_DIR, POWER_DIR))
65        self.host.run('restart powerd')
66
67    def teardown_powerd_prefs(self):
68        """Clean up custom powerd preference changes."""
69        self.host.run('umount %s' % POWER_DIR)
70        self.host.run('restart powerd')
71
72    def run_once(self):
73        if not self.faft_config.has_eventlog:
74            raise error.TestNAError('This board has no eventlog support.')
75
76        logging.info('Verifying eventlog behavior on normal mode boot')
77        self._cutoff_time = self._now()
78        self.switcher.mode_aware_reboot()
79        self.check_state((self.checkers.crossystem_checker, {
80                              'devsw_boot': '0',
81                              'mainfw_type': 'normal',
82                              }))
83        self._gather_events()
84        if not self._has_event(r'System boot'):
85            raise error.TestFail('No "System boot" event on normal boot.')
86        # ' Wake' to match 'FW Wake' and 'ACPI Wake' but not 'Wake Source'
87        if self._has_event(r'Developer Mode|Recovery Mode|Sleep| Wake'):
88            raise error.TestFail('Incorrect event logged on normal boot.')
89
90        logging.debug('Transitioning to dev mode for next test')
91        self.switcher.reboot_to_mode(to_mode='dev')
92
93        logging.info('Verifying eventlog behavior on developer mode boot')
94        self._cutoff_time = self._now()
95        self.switcher.mode_aware_reboot()
96        self.check_state((self.checkers.crossystem_checker, {
97                              'devsw_boot': '1',
98                              'mainfw_type': 'developer',
99                              }))
100        self._gather_events()
101        if (not self._has_event(r'System boot') or
102            not self._has_event(r'Chrome OS Developer Mode')):
103            raise error.TestFail('Missing required event on dev mode boot.')
104        if self._has_event(r'Recovery Mode|Sleep| Wake'):
105            raise error.TestFail('Incorrect event logged on dev mode boot.')
106
107        logging.debug('Transitioning back to normal mode for final tests')
108        self.switcher.reboot_to_mode(to_mode='normal')
109
110        logging.info('Verifying eventlog behavior in recovery mode')
111        self._cutoff_time = self._now()
112        self.switcher.reboot_to_mode(to_mode='rec')
113        logging.debug('Check we booted into recovery')
114        self.check_state((self.checkers.crossystem_checker, {
115                         'mainfw_type': 'recovery',
116                         'recovery_reason' : vboot.RECOVERY_REASON['RO_MANUAL'],
117                         }))
118        self.switcher.mode_aware_reboot()
119        self.check_state((self.checkers.crossystem_checker, {
120                              'devsw_boot': '0',
121                              'mainfw_type': 'normal',
122                              }))
123        self._gather_events()
124        if (not self._has_event(r'System boot') or
125            not self._has_event(r'Chrome OS Recovery Mode \| Recovery Button')):
126            raise error.TestFail('Missing required event in recovery mode.')
127        if self._has_event(r'Developer Mode|Sleep|FW Wake|ACPI Wake \| S3'):
128            raise error.TestFail('Incorrect event logged in recovery mode.')
129
130        logging.info('Verifying eventlog behavior on suspend/resume')
131        self.disable_suspend_to_idle()
132        self._cutoff_time = self._now()
133        self.faft_client.system.run_shell_command(
134                'powerd_dbus_suspend -wakeup_timeout=10')
135        time.sleep(5)   # a little slack time for powerd to write the 'Wake'
136        self.teardown_powerd_prefs()
137        self._gather_events()
138        if ((not self._has_event(r'^Wake') or not self._has_event(r'Sleep')) and
139            (not self._has_event(r'ACPI Enter \| S3') or
140             not self._has_event(r'ACPI Wake \| S3'))):
141            raise error.TestFail('Missing required event on suspend/resume.')
142        if self._has_event(r'System |Developer Mode|Recovery Mode'):
143            raise error.TestFail('Incorrect event logged on suspend/resume.')
144
145        watchdog = WatchdogTester(self.host)
146        if not watchdog.is_supported():
147            logging.info('No hardware watchdog on this platform, skipping')
148        elif self.faft_client.system.run_shell_command_get_output(
149                'crossystem arch')[0] != 'x86': # TODO: Implement event on x86
150            logging.info('Verifying eventlog behavior with hardware watchdog')
151            self._cutoff_time = self._now()
152            with watchdog:
153                watchdog.trigger_watchdog()
154            self._gather_events()
155            if (not self._has_event(r'System boot') or
156                not self._has_event(r'Hardware watchdog reset')):
157                raise error.TestFail('Did not log hardware watchdog event')
158