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