def verify_short_blanking(self):
"""On baytrail systems with a known panel, checks the kernel log for a
message that a short blanking mode has been added."""
logging.info('Running verify_short_blanking')
if self._gpu_type != 'baytrail' or utils.has_no_monitor():
return ''
# Open the EDID to find the panel model.
param_path = '/sys/class/drm/card0-eDP-1/edid'
if not os.path.exists(param_path):
logging.error('Error: %s not found.', param_path)
return self.handle_error(
'Short blanking not added (no EDID found). ')
with open(param_path, 'r') as edp_edid_file:
edp_edid_file.seek(8)
data = edp_edid_file.read(2)
manufacturer = int(struct.unpack('<H', data)[0])
data = edp_edid_file.read(2)
product_code = int(struct.unpack('<H', data)[0])
# This is not the panel we are looking for (AUO B116XTN02.2)
if manufacturer != 0xaf06 or product_code != 0x225c:
return ''
# Get the downclock message from the logs.
reader = cros_logging.LogReader()
reader.set_start_by_reboot(-1)
if not reader.can_find(
'Modified preferred into a short blanking mode'):
return self.handle_error('Short blanking not added. ')
return ''
def _verify_lvds_downclock_mode_added(self):
"""Checks the kernel log for a message that an LVDS downclock mode has
been added.
This test is specific to alex/lumpy/parrot/stout since they use the i915
driver (which has downclocking ability) and use known LCDs. These LCDs
are special, in that they support a downclocked refresh rate, but don't
advertise it in the EDID.
To counteract this, I added a quirk in drm to add a downclocked mode to
the panel. Unfortunately, upstream doesn't want this patch, and we have
to carry it locally. The quirk patch was dropped inadvertently from
chromeos-3.4, so this test ensures we don't regress again.
I plan on writing an upstream friendly patch sometime in the near
future, at which point I'll revert my drm hack and this test.
Returns:
0 if no errors, otherwise the number of errors that occurred.
"""
cmd = 'cat /etc/lsb-release | grep CHROMEOS_RELEASE_BOARD'
output = utils.system_output(cmd)
if ('lumpy' not in output and 'alex' not in output
and 'parrot' not in output and 'stout' not in output):
return 0
# Get the downclock message from the logs
reader = cros_logging.LogReader()
reader.set_start_by_reboot(-1)
if not reader.can_find('Adding LVDS downclock mode'):
logging.error('Error, LVDS downclock quirk not applied!')
return 1
return 0
def run_once(self):
if not 'asan' in utils.read_file('/etc/ui_use_flags.txt'):
raise error.TestFail('Current image not built with ASAN')
extension_path = os.path.join(os.path.dirname(__file__),
'asan_crash_ext')
with chrome.Chrome(extension_paths=[extension_path]) as cr:
pid = utils.get_oldest_pid_by_name('chrome')
asan_log_name = '/var/log/chrome/asan_log.%d' % pid
logging.info('Browser PID under telemetry control is %d. '
'So ASAN log is expected at %s.', pid, asan_log_name)
logging.info('Initiate simulating memory bug to be caught by ASAN.')
extension = cr.get_extension(extension_path)
if not extension:
raise error.TestFail('Failed to find extension %s'
% extension_path)
# Catch the exception raised when the browser crashes.
cr.did_browser_crash(lambda: extension.ExecuteJavaScript(
'chrome.autotestPrivate.simulateAsanMemoryBug();'))
utils.poll_for_condition(
lambda: os.path.isfile(asan_log_name),
timeout=10,
exception=error.TestFail(
'Found no asan log file %s during 10s'
% asan_log_name))
ui_log = cros_logging.LogReader(asan_log_name)
ui_log.read_all_logs()
# We must wait some time until memory bug is simulated (happens
# immediately after the return on the call) and caught by ASAN.
try:
utils.poll_for_condition(
lambda: ui_log.can_find('ERROR: AddressSanitizer'),
timeout=10,
exception=error.TestFail(
'Found no asan log message about '
'Address Sanitizer catch'))
# An example error string is like this
# 'testarray:228' <== Memory access at offset 52 overflows
# this variable
utils.poll_for_condition(
lambda: ui_log.can_find("'testarray"),
timeout=10,
exception=error.TestFail(
'ASAN caught bug but did not mention '
'the cause in the log'))
except:
logging.debug('ASAN log content: ' + ui_log.get_logs())
raise
# The cbuildbot logic will look for asan logs and process them.
# Remove the simulated log file to avoid that.
os.remove(asan_log_name)
def verify_lvds_downclock(self):
"""On systems which support LVDS downclock, checks the kernel log for
a message that an LVDS downclock mode has been added."""
logging.info('Running verify_lvds_downclock')
board = utils.get_board()
if not (board == 'alex' or board == 'lumpy' or board == 'stout'):
return ''
# Get the downclock message from the logs.
reader = cros_logging.LogReader()
reader.set_start_by_reboot(-1)
if not reader.can_find('Adding LVDS downclock mode'):
return self.handle_error('LVDS downclock quirk not applied. ')
return ''
def serve_swf_to_browser(self, browser):
"""
Tries to serve a sample swf to browser.
A failure of this function does not imply a problem with Flash.
@param browser: The Browser object to run the test with.
@return: True if we managed to send swf to browser, False otherwise.
"""
# Prepare index.html/Trivial.swf to be served.
browser.platform.SetHTTPServerDirectories(self.bindir)
test_url = browser.platform.http_server.UrlOf(
os.path.join(self.bindir, 'index.html'))
tab = None
# BUG(485108): Work around a telemetry timing out after login.
try:
logging.info('Getting tab from telemetry...')
tab = browser.tabs[0]
except:
logging.warning('Unexpected exception getting tab: %s',
pprint.pformat(sys.exc_info()[0]))
if tab is None:
return False
logging.info('Initialize reading system logs.')
self._messages_log_reader = cros_logging.LogReader()
self._messages_log_reader.set_start_by_current()
self._ui_log_reader = cros_logging.LogReader('/var/log/ui/ui.LATEST')
self._ui_log_reader.set_start_by_current()
logging.info('Done initializing system logs.')
# Verify that the swf got pulled.
try:
tab.Navigate(test_url)
tab.WaitForDocumentReadyStateToBeComplete()
return True
except:
logging.warning('Unexpected exception waiting for document: %s',
pprint.pformat(sys.exc_info()[0]))
return False
def run_once(self):
# Create magic file to enable browser liveness checking and
# bounce the session manager to pick up the flag file.
cros_ui.stop()
os.mknod(constants.ENABLE_BROWSER_HANG_DETECTION_FILE)
cros_ui.start()
browser_pid = self._get_oldest_pid_by_name(constants.BROWSER)
sm_pid = self._get_oldest_pid_by_name(constants.SESSION_MANAGER)
# Reading the log is the best way to watch for the hang detector.
reader = cros_logging.LogReader()
reader.set_start_by_current()
# To simulate a hang, STOP the browser and wait for it to get
# hit by the session manager. It won't actually exit until it gets
# a SIGCONT, though.
try:
os.kill(browser_pid, signal.SIGSTOP) # Simulate hang.
except OSError as e:
raise error.TestError('Cannot STOP browser: %r' % e)
# Watch for hang detection.
utils.poll_for_condition(
condition=lambda: reader.can_find('Aborting browser process.'),
exception=utils.TimeoutError('Waiting for hang detector.'),
sleep_interval=5,
timeout=60)
try:
os.kill(browser_pid, signal.SIGCONT) # Allow browser to die.
except OSError as e:
raise error.TestError('Cannot CONT browser: %r' % e)
# Wait for old browser process to be gone.
utils.poll_for_condition(
condition= lambda: utils.pid_is_alive(browser_pid),
exception=utils.TimeoutError(
'Browser does not seem to have restarted!'),
timeout=60)
# Wait for new browser to come up.
login.wait_for_browser()
if sm_pid != self._get_oldest_pid_by_name(constants.SESSION_MANAGER):
raise error.TestFail('session_manager seems to have restarted')
def run_once(self, ro_reps=1):
fw_dict = self._index_firmware_avail()
self._usbpd = cros_ec.EC_USBPD()
self._reader = cros_logging.LogReader()
for port in self._usbpd.ports:
if not port.is_dfp():
continue
logging.info('Port%d: is a DFP', port.index)
if not self._is_gfu(port):
continue
logging.info('Port%d: supports GFU', port.index)
self._test_rw_rollback(port, fw_dict)
self._test_ro_only(port, ro_reps)
def run_flash_sanity_test(self, browser, time_to_wait_secs):
"""Run the Flash sanity test.
@param browser: The Browser object to run the test with.
@param time_to_wait_secs: wait time for swf file to load.
"""
tab = None
# BUG(485108): Work around a telemetry timing out after login.
try:
logging.info('Getting tab from telemetry...')
tab = browser.tabs[0]
except:
logging.warning('Unexpected exception getting tab: %s',
pprint.pformat(sys.exc_info()[0]))
if tab is None:
return False
logging.info('Initialize reading system logs.')
self._messages_log_reader = cros_logging.LogReader()
self._messages_log_reader.set_start_by_current()
self._ui_log_reader = cros_logging.LogReader('/var/log/ui/ui.LATEST')
self._ui_log_reader.set_start_by_current()
logging.info('Done initializing system logs.')
# Ensure that the swf got pulled.
pulled = False
try:
latch = self._testServer.add_wait_url('/Trivial.swf')
tab.Navigate(self._test_url)
tab.WaitForDocumentReadyStateToBeComplete()
logging.info('Waiting up to %ds for document.', time_to_wait_secs)
latch.wait(time_to_wait_secs)
pulled = True
except:
logging.warning('Unexpected exception wating for document: %s',
pprint.pformat(sys.exc_info()[0]))
if not pulled:
return False
logging.info('Waiting for Pepper process.')
# Verify that we see a ppapi process and assume it is Flash.
ppapi = utils.wait_for_value_changed(
lambda: (utils.get_process_list('chrome', '--type=ppapi')),
old_value=[],
timeout_sec=5)
logging.info('ppapi process list at start: %s', ', '.join(ppapi))
if not ppapi:
msg = 'flash/platform/pepper/pep_'
if not self._ui_log_reader.can_find(msg):
raise error.TestFail(
'Flash did not start (logs) and no ppapi process found.')
# There is a chrome bug where the command line of the ppapi and
# other processes is shown as "type=zygote". Bail out if we see more
# than 2. Notice, we already did the waiting, so there is no need to
# do more of it.
zygote = utils.get_process_list('chrome', '--type=zygote')
if len(zygote) > 2:
logging.warning(
'Flash probably launched by Chrome as zygote: '
'<%s>.', ', '.join(zygote))
return False
# We have a ppapi process. Let it run for a little and see if it is
# still alive.
logging.info('Running Flash content for a little while.')
time.sleep(5)
logging.info('Verifying the Pepper process is still around.')
ppapi = utils.wait_for_value_changed(
lambda: (utils.get_process_list('chrome', '--type=ppapi')),
old_value=[],
timeout_sec=3)
# Notice that we are not checking for equality of ppapi on purpose.
logging.info('PPapi process list found: <%s>', ', '.join(ppapi))
# Any better pattern matching?
msg = ' Received crash notification for ' + constants.BROWSER
if self._messages_log_reader.can_find(msg):
raise error.TestFail('Browser crashed during test.')
if not ppapi:
raise error.TestFail('Pepper process disappeared during test.')
# At a minimum Flash identifies itself during process start.
msg = 'flash/platform/pepper/pep_'
if not self._ui_log_reader.can_find(msg):
raise error.TestFail('Saw ppapi process but no Flash output.')
return True
def run_once(self, opts=None):
options = dict(filter='',
test_names='', # e.g., dEQP-GLES3.info.version,
# dEQP-GLES2.functional,
# dEQP-GLES3.accuracy.texture, etc.
test_names_file='',
timeout=self._timeout,
subset_to_run='Pass', # Pass, Fail, Timeout, NotPass...
hasty='False',
shard_number='0',
shard_count='1',
debug='False',
perf_failure_description=None)
if opts is None:
opts = []
options.update(utils.args_to_dict(opts))
logging.info('Test Options: %s', options)
self._hasty = (options['hasty'] == 'True')
self._timeout = int(options['timeout'])
self._test_names_file = options['test_names_file']
self._test_names = options['test_names']
self._shard_number = int(options['shard_number'])
self._shard_count = int(options['shard_count'])
self._debug = (options['debug'] == 'True')
if not (self._test_names_file or self._test_names):
self._filter = options['filter']
if not self._filter:
raise error.TestFail('Failed: No dEQP test filter specified')
if options['perf_failure_description']:
self._test_failure_description = options['perf_failure_description']
else:
# Do not report failure if failure description is not specified.
self._test_failure_report_enable = False
# Some information to help post-process logs into blacklists later.
logging.info('ChromeOS BOARD = %s', self._board)
logging.info('ChromeOS CPU family = %s', self._cpu_type)
logging.info('ChromeOS GPU family = %s', self._gpu_type)
# Create a place to put detailed test output logs.
filter_name = self._filter or os.path.basename(self._test_names_file)
logging.info('dEQP test filter = %s', filter_name)
self._log_path = os.path.join(tempfile.gettempdir(), '%s-logs' %
filter_name)
shutil.rmtree(self._log_path, ignore_errors=True)
os.mkdir(self._log_path)
# Load either tests specified by test_names_file, test_names or filter.
test_cases = []
if self._test_names_file:
test_cases = self._get_test_cases_from_names_file()
elif self._test_names:
test_cases = []
for name in self._test_names.split(','):
test_cases.extend(self._get_test_cases(name, 'Pass'))
elif self._filter:
test_cases = self._get_test_cases(self._filter,
options['subset_to_run'])
if self._debug:
# LogReader works on /var/log/messages by default.
self._log_reader = cros_logging.LogReader()
self._log_reader.set_start_by_current()
# Assume all tests failed at the beginning.
for test_case in test_cases:
self.add_failures(test_case)
test_results, failing_test = self._run_once(test_cases)
# Rerun the test if we are in hasty mode.
if self._hasty and len(failing_test) > 0:
if len(failing_test) < sum(test_results.values()) * RERUN_RATIO:
logging.info("Because we are in hasty mode, we will rerun the "
"failing tests one at a time")
rerun_results, failing_test = self._run_once(failing_test)
# Update failing test result from the test_results
for result in test_results:
if result.lower() not in self.TEST_RESULT_FILTER:
test_results[result] = 0
for result in rerun_results:
test_results[result] = (test_results.get(result, 0) +
rerun_results[result])
else:
logging.info("There are too many failing tests. It would "
"take too long to rerun them. Giving up.")
# Update failing tests to the chrome perf dashboard records.
for test_case in test_cases:
if test_case not in failing_test:
self.remove_failures(test_case)
logging.info('Test results:')
logging.info(test_results)
logging.debug('Test Failed: %s', failing_test)
self.write_perf_keyval(test_results)
test_count = 0
test_failures = 0
test_passes = 0
test_skipped = 0
for result in test_results:
test_count += test_results[result]
if result.lower() in ['pass']:
test_passes += test_results[result]
if result.lower() not in self.TEST_RESULT_FILTER:
test_failures += test_results[result]
if result.lower() in ['skipped']:
test_skipped += test_results[result]
# The text "Completed all tests." is used by the process_log.py script
# and should always appear at the end of a completed test run.
logging.info(
'Completed all tests. Saw %d tests, %d passes and %d failures.',
test_count, test_passes, test_failures)
if self._filter and test_count == 0 and options[
'subset_to_run'] != 'NotPass':
logging.warning('No test cases found for filter: %s!', self._filter)
if test_failures:
raise error.TestFail('Failed: on %s %d/%d tests failed.' %
(self._gpu_type, test_failures, test_count))
if test_skipped > 0:
logging.info('On %s %d tests skipped, %d passes' %
(self._gpu_type, test_skipped, test_passes))
def run_once(self, opts=None):
options = dict(
filter='',
test_names='', # e.g., dEQP-GLES3.info.version,
# dEQP-GLES2.functional,
# dEQP-GLES3.accuracy.texture, etc.
test_names_file='',
timeout=self._timeout,
subset_to_run='Pass', # Pass, Fail, Timeout, NotPass...
hasty='False',
shard_number='0',
shard_count='1',
debug='False')
if opts is None:
opts = []
options.update(utils.args_to_dict(opts))
logging.info('Test Options: %s', options)
self._hasty = (options['hasty'] == 'True')
self._timeout = int(options['timeout'])
self._test_names_file = options['test_names_file']
self._test_names = options['test_names']
self._shard_number = int(options['shard_number'])
self._shard_count = int(options['shard_count'])
self._debug = (options['debug'] == 'True')
if not (self._test_names_file or self._test_names):
self._filter = options['filter']
if not self._filter:
raise error.TestFail('Failed: No dEQP test filter specified')
# Some information to help postprocess logs into blacklists later.
logging.info('ChromeOS BOARD = %s', self._board)
logging.info('ChromeOS CPU family = %s', self._cpu_type)
logging.info('ChromeOS GPU family = %s', self._gpu_type)
# Create a place to put detailed test output logs.
if self._filter:
logging.info('dEQP test filter = %s', self._filter)
self._log_path = os.path.join(tempfile.gettempdir(),
'%s-logs' % self._filter)
else:
base = os.path.basename(self._test_names_file)
# TODO(ihf): Clean this up.
logging.info('dEQP test filter = %s', os.path.splitext(base)[0])
self._log_path = os.path.join(tempfile.gettempdir(),
'%s-logs' % base)
shutil.rmtree(self._log_path, ignore_errors=True)
os.mkdir(self._log_path)
self._services.stop_services()
if self._test_names_file:
test_cases = [
line.rstrip('\n') for line in open(
os.path.join(self.bindir, self._test_names_file))
]
test_cases = [
test for test in test_cases if test and not test.isspace()
]
if self._test_names:
test_cases = []
for name in self._test_names.split(','):
test_cases.extend(self._get_test_cases(name, 'Pass'))
if self._filter:
test_cases = self._get_test_cases(self._filter,
options['subset_to_run'])
if self._debug:
# LogReader works on /var/log/messages by default.
self._log_reader = cros_logging.LogReader()
self._log_reader.set_start_by_current()
test_results = {}
if self._hasty:
logging.info('Running in hasty mode.')
test_results = self.run_tests_hasty(test_cases)
else:
logging.info('Running each test individually.')
test_results = self.run_tests_individually(test_cases)
logging.info('Test results:')
logging.info(test_results)
self.write_perf_keyval(test_results)
test_count = 0
test_failures = 0
test_passes = 0
test_skipped = 0
for result in test_results:
test_count += test_results[result]
if result.lower() in ['pass']:
test_passes += test_results[result]
if result.lower() not in [
'pass', 'notsupported', 'internalerror', 'qualitywarning',
'compatibilitywarning', 'skipped'
]:
test_failures += test_results[result]
if result.lower() in ['skipped']:
test_skipped += test_results[result]
# The text "Completed all tests." is used by the process_log.py script
# and should always appear at the end of a completed test run.
logging.info(
'Completed all tests. Saw %d tests, %d passes and %d failures.',
test_count, test_passes, test_failures)
if self._filter and test_count == 0 and options[
'subset_to_run'] != 'NotPass':
logging.warning('No test cases found for filter: %s!',
self._filter)
if options['subset_to_run'] == 'NotPass':
if test_passes:
# TODO(ihf): Make this an annotated TestPass once available.
raise error.TestWarn(
'%d formerly failing tests are passing now.' % test_passes)
elif test_failures:
# TODO(ihf): Delete this once hasty expectations have been
# checked in.
if self._gpu_type.startswith('tegra'):
raise error.TestWarn(
'Failed: on %s %d/%d tests failed.' %
(self._gpu_type, test_failures, test_count))
raise error.TestFail('Failed: on %s %d/%d tests failed.' %
(self._gpu_type, test_failures, test_count))
if test_skipped > 0:
raise error.TestFail('Failed: on %s %d tests skipped, %d passes' %
(self._gpu_type, test_skipped, test_passes))