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