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 5 import logging, re, time 6 7 from autotest_lib.client.common_lib import error 8 from autotest_lib.server.cros.faft.firmware_test import FirmwareTest 9 10 11 class firmware_EventLog(FirmwareTest): 12 """ 13 Test to ensure eventlog is written on boot and suspend/resume. 14 """ 15 version = 1 16 17 _TIME_FORMAT = '%Y-%m-%d %H:%M:%S' 18 19 def initialize(self, host, cmdline_args): 20 super(firmware_EventLog, self).initialize(host, cmdline_args) 21 self.switcher.setup_mode('normal') 22 23 def _has_event(self, pattern): 24 return bool(filter(re.compile(pattern).search, self._events)) 25 26 def _gather_events(self): 27 entries = self.faft_client.system.run_shell_command_get_output( 28 'mosys eventlog list') 29 now = self._now() 30 self._events = [] 31 for line in reversed(entries): 32 _, time_string, event = line.split(' | ', 2) 33 timestamp = time.strptime(time_string, self._TIME_FORMAT) 34 if timestamp > now: 35 logging.error('Found prophecy: "%s"', line) 36 raise error.TestFail('Event timestamp lies in the future') 37 if timestamp < self._cutoff_time: 38 logging.debug('Event "%s" too early, stopping search', line) 39 break 40 logging.info('Found event: "%s"', line) 41 self._events.append(event) 42 43 # This assumes that Linux and the firmware use the same RTC. mosys converts 44 # timestamps to localtime, and so do we (by calling date without --utc). 45 def _now(self): 46 time_string = self.faft_client.system.run_shell_command_get_output( 47 'date +"%s"' % self._TIME_FORMAT)[0] 48 logging.debug('Current local system time on DUT is "%s"', time_string) 49 return time.strptime(time_string, self._TIME_FORMAT) 50 51 def run_once(self): 52 if not self.faft_config.has_eventlog: 53 raise error.TestNAError('This board has no eventlog support.') 54 55 logging.info('Verifying eventlog behavior on normal mode boot') 56 self._cutoff_time = self._now() 57 self.switcher.mode_aware_reboot() 58 self.check_state((self.checkers.crossystem_checker, { 59 'devsw_boot': '0', 60 'mainfw_type': 'normal', 61 })) 62 self._gather_events() 63 if not self._has_event(r'System boot'): 64 raise error.TestError('No "System boot" event on normal boot.') 65 # ' Wake' to match 'FW Wake' and 'ACPI Wake' but not 'Wake Source' 66 if self._has_event(r'Developer Mode|Recovery Mode|Sleep| Wake'): 67 raise error.TestError('Incorrect event logged on normal boot.') 68 69 logging.debug('Transitioning to dev mode for next test') 70 self.switcher.reboot_to_mode(to_mode='dev') 71 72 logging.info('Verifying eventlog behavior on developer mode boot') 73 self._cutoff_time = self._now() 74 self.switcher.mode_aware_reboot() 75 self.check_state((self.checkers.crossystem_checker, { 76 'devsw_boot': '1', 77 'mainfw_type': 'developer', 78 })) 79 self._gather_events() 80 if (not self._has_event(r'System boot') or 81 not self._has_event(r'Chrome OS Developer Mode')): 82 raise error.TestError('Missing required event on dev mode boot.') 83 if self._has_event(r'Recovery Mode|Sleep| Wake'): 84 raise error.TestError('Incorrect event logged on dev mode boot.') 85 86 logging.debug('Transitioning back to normal mode for final tests') 87 self.switcher.reboot_to_mode(to_mode='normal') 88 89 logging.info('Verifying eventlog behavior in recovery mode') 90 self._cutoff_time = self._now() 91 self.switcher.reboot_to_mode(to_mode='rec', wait_for_dut_up=False) 92 self.switcher.wait_for_client_offline() 93 time.sleep(self.faft_config.firmware_screen) 94 self.switcher.mode_aware_reboot(sync_before_boot=False) 95 self.check_state((self.checkers.crossystem_checker, { 96 'devsw_boot': '0', 97 'mainfw_type': 'normal', 98 })) 99 self._gather_events() 100 if (not self._has_event(r'System boot') or 101 not self._has_event(r'Chrome OS Recovery Mode \| Recovery Button')): 102 raise error.TestError('Missing required event in recovery mode.') 103 if self._has_event(r'Developer Mode|Sleep|FW Wake|ACPI Wake \| S3'): 104 raise error.TestError('Incorrect event logged in recovery mode.') 105 106 logging.info('Verifying eventlog behavior on suspend/resume') 107 self._cutoff_time = self._now() 108 self.faft_client.system.run_shell_command( 109 'powerd_dbus_suspend -wakeup_timeout=10') 110 time.sleep(5) # a little slack time for powerd to write the 'Wake' 111 self._gather_events() 112 if ((not self._has_event(r'^Wake') or not self._has_event(r'Sleep')) and 113 (not self._has_event(r'ACPI Enter \| S3') or 114 not self._has_event(r'ACPI Wake \| S3'))): 115 raise error.TestError('Missing required event on suspend/resume.') 116 if self._has_event(r'System |Developer Mode|Recovery Mode'): 117 raise error.TestError('Incorrect event logged on suspend/resume.') 118
