Add firmware_EventLog test to verify event log generation and timestamps
This patch adds a new faft_lv4 test to validate the functionality of the
firmware event log. It will boot the system in normal, developer and
recovery mode, verifying that the right events are logged for each. It
also tests a suspend/resume cycle, allowing either the ACPI events used
on x86 boards or the userspace Sleep/Wake events introduced with Spring
and Pit. (We can't check for 'FW Wake' because not all not-x86 boards
have a resume component in firmware.) The events are correlated to the
test section they were generated in by their timestamps, so this also
confirms that accurate timestamps are generated.
CQ-DEPEND=CL:238467
BUG=chrome-os-partner:34108
TEST=Tested on Falco (ToT), Blaze (ToT) and Pi (release). Pi failed in
the expected manner because U-Boot is missing RTC support (and all
timestamps are added as 2000-00-00). Blaze failed because its
timestamps' months are off by one... turns out the RTC driver code was
incorrectly copied from the 0-based-month-using kernel to our
1-based-month-using coreboot.
Change-Id: I2760080030468ed71dd0b7359ac69a269f6ab47a
Signed-off-by: Julius Werner <jwerner@chromium.org>
Reviewed-on: https://chromium-review.googlesource.com/238078
Reviewed-by: Yusuf Mohsinally <mohsinally@chromium.org>
diff --git a/server/cros/faft/config/DEFAULTS.py b/server/cros/faft/config/DEFAULTS.py
index ff19d61..0068adb 100644
--- a/server/cros/faft/config/DEFAULTS.py
+++ b/server/cros/faft/config/DEFAULTS.py
@@ -43,6 +43,10 @@
[0x61, 'press'],
[0x61, 'release']]
+ # Has eventlog support including proper timestamps. (Only for old boards!
+ # Never disable this "temporarily, until we get around to implementing it"!)
+ has_eventlog = True
+
# Delay between power-on and firmware screen
firmware_screen = 10
diff --git a/server/cros/faft/config/alex.py b/server/cros/faft/config/alex.py
index 58ae235..3f4304c 100644
--- a/server/cros/faft/config/alex.py
+++ b/server/cros/faft/config/alex.py
@@ -9,3 +9,4 @@
"""FAFT config values for Alex."""
keyboard_dev = False
gbb_version = 1.0
+ has_eventlog = False
diff --git a/server/cros/faft/config/lumpy.py b/server/cros/faft/config/lumpy.py
index 85e68c7..9158349 100644
--- a/server/cros/faft/config/lumpy.py
+++ b/server/cros/faft/config/lumpy.py
@@ -8,3 +8,4 @@
class Values(object):
"""FAFT config values for Lumpy."""
keyboard_dev = False
+ has_eventlog = False
diff --git a/server/cros/faft/config/nyan.py b/server/cros/faft/config/nyan.py
index befd786..0163c72 100644
--- a/server/cros/faft/config/nyan.py
+++ b/server/cros/faft/config/nyan.py
@@ -14,3 +14,4 @@
dev_screen = 4
firmware_screen = 4
wp_voltage = 'off'
+ has_eventlog = False # Shipped without RTC support in firmware
diff --git a/server/cros/faft/config/pi.py b/server/cros/faft/config/pi.py
index 9c07b30..a11a932 100644
--- a/server/cros/faft/config/pi.py
+++ b/server/cros/faft/config/pi.py
@@ -9,3 +9,4 @@
"""FAFT config values for Pi."""
chrome_ec = True
ec_capability = (['battery', 'keyboard', 'arm', 'lid'])
+ has_eventlog = False # No RTC support in firmware
diff --git a/server/cros/faft/config/pit.py b/server/cros/faft/config/pit.py
index c71689e..30f6e6f 100644
--- a/server/cros/faft/config/pit.py
+++ b/server/cros/faft/config/pit.py
@@ -9,3 +9,4 @@
"""FAFT config values for Pit."""
chrome_ec = True
ec_capability = (['battery', 'keyboard', 'arm', 'lid'])
+ has_eventlog = False # No RTC support in firmware
diff --git a/server/cros/faft/config/skate.py b/server/cros/faft/config/skate.py
index b26d534..497e36c 100644
--- a/server/cros/faft/config/skate.py
+++ b/server/cros/faft/config/skate.py
@@ -11,3 +11,4 @@
chrome_ec = True
use_u_boot = True
ec_capability = (['battery', 'keyboard', 'arm', 'lid'])
+ has_eventlog = False # No RTC support in firmware
diff --git a/server/cros/faft/config/snow.py b/server/cros/faft/config/snow.py
index 21ffb45..b4a50fd 100644
--- a/server/cros/faft/config/snow.py
+++ b/server/cros/faft/config/snow.py
@@ -11,3 +11,4 @@
ec_capability = (['battery', 'keyboard', 'arm'])
ec_boot_to_console = 0.4
use_u_boot = True
+ has_eventlog = False
diff --git a/server/cros/faft/config/spring.py b/server/cros/faft/config/spring.py
index 03daccd..37f33b3 100644
--- a/server/cros/faft/config/spring.py
+++ b/server/cros/faft/config/spring.py
@@ -11,3 +11,4 @@
chrome_ec = True
use_u_boot = True
ec_capability = (['battery', 'keyboard', 'arm', 'lid'])
+ has_eventlog = False # No RTC support in firmware
diff --git a/server/cros/faft/config/stumpy.py b/server/cros/faft/config/stumpy.py
index 5a158e4..0683461 100644
--- a/server/cros/faft/config/stumpy.py
+++ b/server/cros/faft/config/stumpy.py
@@ -10,3 +10,4 @@
has_lid = False
has_keyboard = False
keyboard_dev = False
+ has_eventlog = False
diff --git a/server/cros/faft/config/zgb.py b/server/cros/faft/config/zgb.py
index d786dd3..bbe7fff 100644
--- a/server/cros/faft/config/zgb.py
+++ b/server/cros/faft/config/zgb.py
@@ -9,3 +9,4 @@
"""FAFT config values for ZGB."""
keyboard_dev = False
gbb_version = 1.0
+ has_eventlog = False
diff --git a/server/site_tests/firmware_EventLog/control b/server/site_tests/firmware_EventLog/control
new file mode 100644
index 0000000..052a83e
--- /dev/null
+++ b/server/site_tests/firmware_EventLog/control
@@ -0,0 +1,30 @@
+# Copyright 2014 The Chromium OS Authors. All rights reserved.
+# Use of this source code is governed by a BSD-style license that can be
+# found in the LICENSE file.
+
+from autotest_lib.server import utils
+
+AUTHOR = "jwerner"
+NAME = "firmware_EventLog"
+PURPOSE = "Ensure eventlog is written correctly on boot and suspend/resume."
+CRITERIA = "This test will fail if entries are missing or have a bad timestamp."
+SUITE = "faft,faft_bios,faft_normal,faft_lv4"
+TIME = "SHORT"
+TEST_CATEGORY = "Functional"
+TEST_CLASS = "firmware"
+TEST_TYPE = "server"
+
+DOC = """
+This test ensures that correct event log entries are written after a boot and
+a suspend-resume cycle.
+"""
+
+args_dict = utils.args_to_dict(args)
+servo_args = hosts.CrosHost.get_servo_arguments(args_dict)
+
+def run_eventlog(machine):
+ host = hosts.create_host(machine, servo_args=servo_args)
+ job.run_test("firmware_EventLog", host=host, cmdline_args=args,
+ disable_sysinfo=True, dev_mode=False)
+
+parallel_simple(run_eventlog, machines)
diff --git a/server/site_tests/firmware_EventLog/firmware_EventLog.py b/server/site_tests/firmware_EventLog/firmware_EventLog.py
new file mode 100644
index 0000000..5bee072
--- /dev/null
+++ b/server/site_tests/firmware_EventLog/firmware_EventLog.py
@@ -0,0 +1,120 @@
+# Copyright 2014 The Chromium OS Authors. All rights reserved.
+# Use of this source code is governed by a BSD-style license that can be
+# found in the LICENSE file.
+
+import logging, re, time
+
+from autotest_lib.client.common_lib import error
+from autotest_lib.server.cros.faft.firmware_test import FirmwareTest
+
+
+class firmware_EventLog(FirmwareTest):
+ """
+ Test to ensure eventlog is written on boot and suspend/resume.
+ """
+ version = 1
+
+ _TIME_FORMAT = '%Y-%m-%d %H:%M:%S'
+
+ def initialize(self, host, cmdline_args):
+ super(firmware_EventLog, self).initialize(host, cmdline_args)
+ self.setup_dev_mode(dev_mode=False)
+
+ def _has_event(self, pattern):
+ return bool(filter(re.compile(pattern).search, self._events))
+
+ def _gather_events(self):
+ entries = self.faft_client.system.run_shell_command_get_output(
+ 'mosys eventlog list')
+ now = self._now()
+ self._events = []
+ for line in reversed(entries):
+ _, time_string, event = line.split(' | ', 2)
+ timestamp = time.strptime(time_string, self._TIME_FORMAT)
+ if timestamp > now:
+ logging.error('Found prophecy: "%s"', line)
+ raise error.TestFail('Event timestamp lies in the future')
+ if timestamp < self._cutoff_time:
+ logging.debug('Event "%s" too early, stopping search', line)
+ break
+ logging.info('Found event: "%s"', line)
+ self._events.append(event)
+
+ # This assumes that Linux and the firmware use the same RTC. mosys converts
+ # timestamps to localtime, and so do we (by calling date without --utc).
+ def _now(self):
+ time_string = self.faft_client.system.run_shell_command_get_output(
+ 'date +"%s"' % self._TIME_FORMAT)[0]
+ logging.debug('Current local system time on DUT is "%s"', time_string)
+ return time.strptime(time_string, self._TIME_FORMAT)
+
+ def run_once(self):
+ if not self.faft_config.has_eventlog:
+ raise error.TestNAError('This board has no eventlog support.')
+
+ logging.info('Verifying eventlog behavior on normal mode boot')
+ self._cutoff_time = self._now()
+ self.reboot_warm()
+ self.check_state((self.checkers.crossystem_checker, {
+ 'devsw_boot': '0',
+ 'mainfw_type': 'normal',
+ }))
+ self._gather_events()
+ if not self._has_event(r'System boot'):
+ raise error.TestError('No "System boot" event on normal boot.')
+ # ' Wake' to match 'FW Wake' and 'ACPI Wake' but not 'Wake Source'
+ if self._has_event(r'Developer Mode|Recovery Mode|Sleep| Wake'):
+ raise error.TestError('Incorrect event logged on normal boot.')
+
+ logging.debug('Transitioning to dev mode for next test')
+ self.enable_dev_mode_and_reboot()
+ self.wait_dev_screen_and_ctrl_d()
+ self.wait_for_client()
+
+ logging.info('Verifying eventlog behavior on developer mode boot')
+ self._cutoff_time = self._now()
+ self.reboot_warm(ctrl_d=True)
+ self.check_state((self.checkers.crossystem_checker, {
+ 'devsw_boot': '1',
+ 'mainfw_type': 'developer',
+ }))
+ self._gather_events()
+ if (not self._has_event(r'System boot') or
+ not self._has_event(r'Chrome OS Developer Mode')):
+ raise error.TestError('Missing required event on dev mode boot.')
+ if self._has_event(r'Recovery Mode|Sleep| Wake'):
+ raise error.TestError('Incorrect event logged on dev mode boot.')
+
+ logging.debug('Transitioning back to normal mode for final tests')
+ self.enable_normal_mode_and_reboot()
+ self.wait_for_client()
+
+ logging.info('Verifying eventlog behavior in recovery mode')
+ self._cutoff_time = self._now()
+ self.enable_rec_mode_and_reboot()
+ self.wait_for_client_offline()
+ time.sleep(self.faft_config.firmware_screen)
+ self.reboot_warm(sync_before_boot=False)
+ self.check_state((self.checkers.crossystem_checker, {
+ 'devsw_boot': '0',
+ 'mainfw_type': 'normal',
+ }))
+ self._gather_events()
+ if (not self._has_event(r'System boot') or
+ not self._has_event(r'Chrome OS Recovery Mode \| Recovery Button')):
+ raise error.TestError('Missing required event in recovery mode.')
+ if self._has_event(r'Developer Mode|Sleep| Wake'):
+ raise error.TestError('Incorrect event logged in recovery mode.')
+
+ logging.info('Verifying eventlog behavior on suspend/resume')
+ self._cutoff_time = self._now()
+ self.faft_client.system.run_shell_command(
+ 'powerd_dbus_suspend -wakeup_timeout=10')
+ time.sleep(5) # a little slack time for powerd to write the 'Wake'
+ self._gather_events()
+ if ((not self._has_event(r'^Wake') or not self._has_event(r'Sleep')) and
+ (not self._has_event(r'ACPI Enter \| S3') or
+ not self._has_event(r'ACPI Wake \| S3'))):
+ raise error.TestError('Missing required event on suspend/resume.')
+ if self._has_event(r'System |Developer Mode|Recovery Mode'):
+ raise error.TestError('Incorrect event logged on suspend/resume.')
