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