Clean up extreme verbosity of logs in test harness.
In addition fix a bug where we track the wrong parallel job on the job pool.
In addition fix bug where we unittest harnesses randomly hangs while trying to write to stderr while finding update candidates.
Change-Id: I1449501606a57c5324eafc74c4fc388fbbe2bee3
BUG=chromium-os:12950
TEST=Ran with -q and full test suite and emulated errors
when necessary to see errors printed out only failures.
Review URL: http://codereview.chromium.org/6857004
diff --git a/au_test_harness/au_test.py b/au_test_harness/au_test.py
index a95fa74..8b1df08 100644
--- a/au_test_harness/au_test.py
+++ b/au_test_harness/au_test.py
@@ -81,11 +81,11 @@
self.worker.UpdateUsingPayload(payload)
except UpdateException as err:
# Will raise ValueError if expected is not found.
- if re.search(re.escape(expected_msg), err.stdout, re.MULTILINE):
+ if re.search(re.escape(expected_msg), err.output, re.MULTILINE):
return
else:
cros_lib.Warning("Didn't find '%s' in:" % expected_msg)
- cros_lib.Warning(err.stdout)
+ cros_lib.Warning(err.output)
self.fail('We managed to update when failure was expected')
@@ -114,7 +114,7 @@
Sets instance specific variables and initializes worker.
"""
- unittest.TestCase.setUp(self)
+ super(AUTest, self).setUp()
self.worker = self.worker_class(self.options, AUTest.test_results_root)
self.download_folder = os.path.join(os.path.realpath(os.path.curdir),
'latest_download')
diff --git a/au_test_harness/au_worker.py b/au_test_harness/au_worker.py
index a25de7f..3f8caa8 100644
--- a/au_test_harness/au_worker.py
+++ b/au_test_harness/au_worker.py
@@ -48,6 +48,17 @@
"""Called at the end of every test."""
pass
+ def GetUpdateMessage(self, update_target, update_base, from_vm, proxy):
+ if update_base:
+ str = 'Performing a delta update from %s to %s' % (
+ update_base, update_target)
+ else:
+ str = 'Performing a full update to %s' % update_target
+
+ if from_vm: str += ' in a VM'
+ if proxy: ' using a proxy on port %s' % proxy
+ return str
+
def UpdateImage(self, image_path, src_image_path='', stateful_change='old',
proxy_port=None, private_key_path=None):
"""Implementation of an actual update.
@@ -111,19 +122,14 @@
private_key_path: Path to a private key to use with update payload.
Raises an update_exception.UpdateException if _UpdateImage returns an error.
"""
- try:
- if not self.use_delta_updates: src_image_path = ''
- if private_key_path:
- key_to_use = private_key_path
- else:
- key_to_use = self.private_key
+ if not self.use_delta_updates: src_image_path = ''
+ if private_key_path:
+ key_to_use = private_key_path
+ else:
+ key_to_use = self.private_key
- self.UpdateImage(image_path, src_image_path, stateful_change,
- proxy_port, key_to_use)
- except update_exception.UpdateException as err:
- # If the update fails, print it out
- Warning(err.stdout)
- raise
+ self.UpdateImage(image_path, src_image_path, stateful_change,
+ proxy_port, key_to_use)
@classmethod
def SetUpdateCache(cls, update_cache):
@@ -161,7 +167,6 @@
'--test_image'
], enter_chroot=True, cwd=self.crosutils)
- cros_lib.Info('Using %s as base' % self.vm_image_path)
assert os.path.exists(self.vm_image_path)
def GetStatefulChangeFlag(self, stateful_change):
@@ -179,7 +184,6 @@
Modifies cmd in places by appending appropriate items given args.
"""
if proxy_port: cmd.append('--proxy_port=%s' % proxy_port)
-
# Get pregenerated update if we have one.
update_id = dev_server_wrapper.GenerateUpdateId(image_path, src_image_path,
private_key_path)
@@ -200,17 +204,18 @@
if self.verbose:
try:
if log_directory:
- cros_lib.RunCommand(cmd, log_to_file=os.path.join(log_directory,
- 'update.log'))
+ cros_lib.RunCommand(
+ cmd, log_to_file=os.path.join(log_directory, 'update.log'),
+ print_cmd=False)
else:
- cros_lib.RunCommand(cmd)
- except Exception as e:
- Warning(str(e))
+ cros_lib.RunCommand(cmd, print_cmd=False)
+ except cros_lib.RunCommandException as e:
raise update_exception.UpdateException(1, str(e))
else:
- (code, stdout, stderr) = cros_lib.RunCommandCaptureOutput(cmd)
+ (code, stdout, unused_stderr) = cros_lib.RunCommandCaptureOutput(
+ cmd, print_cmd=False)
if code != 0:
- Warning(stdout)
+ cros_lib.Warning(stdout)
raise update_exception.UpdateException(code, stdout)
def AssertEnoughTestsPassed(self, unittest, output, percent_required_to_pass):
@@ -223,15 +228,19 @@
Returns:
percent that passed.
"""
- cros_lib.Info('Output from VerifyImage():')
- print >> sys.stderr, output
- sys.stderr.flush()
percent_passed = self._ParseGenerateTestReportOutput(output)
- cros_lib.Info('Percent passed: %d vs. Percent required: %d' % (
+ self.TestInfo('Percent passed: %d vs. Percent required: %d' % (
percent_passed, percent_required_to_pass))
- unittest.assertTrue(percent_passed >= percent_required_to_pass)
+ if percent_passed < percent_required_to_pass:
+ print output
+ unittest.fail('%d percent of tests are required to pass' %
+ percent_required_to_pass)
+
return percent_passed
+ def TestInfo(self, message):
+ cros_lib.Info('%s: %s' % (self.test_name, message))
+
def Initialize(self, port):
"""Initializes test specific variables for each test.
@@ -245,8 +254,9 @@
self._kvm_pid_file = '/tmp/kvm.%d' % port
# Initialize test results directory.
- test_name = inspect.stack()[1][3]
- self.results_directory = os.path.join(self.test_results_root, test_name)
+ self.test_name = inspect.stack()[1][3]
+ self.results_directory = os.path.join(self.test_results_root,
+ self.test_name)
self.results_count = 0
def GetNextResultsPath(self, label):
@@ -276,7 +286,6 @@
if line.startswith("Total PASS:"):
# FORMAT: ^TOTAL PASS: num_passed/num_total (percent%)$
percent_passed = line.split()[3].strip('()%')
- cros_lib.Info('Percent of tests passed %s' % percent_passed)
break
return int(percent_passed)
diff --git a/au_test_harness/cros_au_test_harness.py b/au_test_harness/cros_au_test_harness.py
index dc6572a..3257999 100755
--- a/au_test_harness/cros_au_test_harness.py
+++ b/au_test_harness/cros_au_test_harness.py
@@ -68,7 +68,18 @@
command.append('--private_key=%s' %
cros_lib.ReinterpretPathForChroot(private_key_path))
- return cros_lib.RunCommand(command, enter_chroot=True, print_cmd=True,
+ if src:
+ debug_message = 'delta update payload from %s to %s' % (target, src)
+ else:
+ debug_message = 'full update payload to %s' % target
+
+ if private_key_path:
+ debug_message = 'Generating a signed ' + debug_message
+ else:
+ debug_message = 'Generating an unsigned ' + debug_message
+
+ cros_lib.Info(debug_message)
+ return cros_lib.RunCommand(command, enter_chroot=True, print_cmd=False,
cwd=cros_lib.GetCrosUtilsPath(),
log_to_file=log_file, error_ok=True,
exit_code=True)
@@ -106,12 +117,11 @@
# Use dummy class to mock out updates that would be run as part of a test.
test_suite = _PrepareTestSuite(options, use_dummy_worker=True)
- test_result = unittest.TextTestRunner(verbosity=0).run(test_suite)
+ test_result = unittest.TextTestRunner(
+ stream=open(os.devnull, 'w')).run(test_suite)
if not test_result.wasSuccessful():
raise update_exception.UpdateException(1,
'Error finding updates to generate.')
-
- cros_lib.Info('The following delta updates are required.')
update_ids = []
jobs = []
args = []
@@ -126,7 +136,6 @@
# TODO(sosa): Add private key as part of caching name once devserver can
# handle it its own cache.
update_id = dev_server_wrapper.GenerateUpdateId(target, src, key)
- print >> sys.stderr, 'AU: %s' % update_id
update_ids.append(update_id)
jobs.append(_GenerateVMUpdate)
args.append((target, src, key, log_file))
@@ -143,6 +152,7 @@
manager.AddKeyToImage()
au_test.AUTest.public_key_managers.append(manager)
+ cros_lib.Info('Generating updates required for this test suite in parallel.')
error_codes = parallel_test_job.RunParallelJobs(options.jobs, jobs, args)
results = _ProcessGeneratorOutputs(log_files, error_codes)
@@ -162,13 +172,16 @@
for test in test_suite:
test_name = test.id()
test_case = unittest.TestLoader().loadTestsFromName(test_name)
- threads.append(unittest.TextTestRunner(verbosity=2).run)
+ threads.append(unittest.TextTestRunner().run)
args.append(test_case)
+ cros_lib.Info('Running tests in test suite in parallel.')
results = parallel_test_job.RunParallelJobs(options.jobs, threads, args)
for test_result in results:
if not test_result.wasSuccessful():
- cros_lib.Die('Test harness was not successful')
+ cros_lib.Die(
+ 'Test harness was not successful. See logs for details. '
+ 'Note: Ignore max recursion depth errors crosbug.com/14274')
def _CleanPreviousWork(options):
@@ -269,7 +282,7 @@
# TODO(sosa) - Take in a machine pool for a real test.
# Can't run in parallel with only one remote device.
test_suite = _PrepareTestSuite(options)
- test_result = unittest.TextTestRunner(verbosity=2).run(test_suite)
+ test_result = unittest.TextTestRunner().run(test_suite)
if not test_result.wasSuccessful(): cros_lib.Die('Test harness failed.')
finally:
diff --git a/au_test_harness/dummy_au_worker.py b/au_test_harness/dummy_au_worker.py
index fa1bee0..178d79d 100644
--- a/au_test_harness/dummy_au_worker.py
+++ b/au_test_harness/dummy_au_worker.py
@@ -6,6 +6,8 @@
import unittest
+import cros_build_lib as cros_lib
+
import au_worker
class DummyAUWorker(au_worker.AUWorker):
@@ -19,7 +21,7 @@
delta_list = {}
def __init__(self, options, test_results_root):
- au_worker.AUWorker.__init__(self, options, test_results_root)
+ super(DummyAUWorker, self).__init__(options, test_results_root)
self.au_type = options.type
def PrepareBase(self, image_path):
diff --git a/au_test_harness/parallel_test_job.py b/au_test_harness/parallel_test_job.py
index 5c563a0..589b0af 100644
--- a/au_test_harness/parallel_test_job.py
+++ b/au_test_harness/parallel_test_job.py
@@ -64,17 +64,22 @@
if not active_job:
active_job = parallel_job
- return (active_count, parallel_job)
+ return (active_count, active_job)
+ first_time = True
start_time = time.time()
while (time.time() - start_time) < cls.MAX_TIMEOUT_SECONDS:
(active_count, active_job) = GetCurrentActiveCount()
if active_count == 0:
return
else:
- print >> sys.stderr, (
- 'Process Pool Active: Waiting on %d/%d jobs to complete' %
- (active_count, len(parallel_jobs)))
+ if not first_time:
+ print (
+ 'Process Pool Active: Waiting on %d/%d jobs to complete' %
+ (active_count, len(parallel_jobs)))
+ else:
+ first_time = False
+
active_job.join(cls.SLEEP_TIMEOUT_SECONDS)
time.sleep(5) # Prevents lots of printing out as job is ending.
diff --git a/au_test_harness/real_au_worker.py b/au_test_harness/real_au_worker.py
index ffd9963..21666c0 100644
--- a/au_test_harness/real_au_worker.py
+++ b/au_test_harness/real_au_worker.py
@@ -15,7 +15,7 @@
def __init__(self, options, test_results_root):
"""Processes non-vm-specific options."""
- au_worker.AUWorker.__init__(self, options, test_results_root)
+ super(RealAUWorker, self).__init__(options, test_results_root)
self.remote = options.remote
if not self.remote: cros_lib.Die('We require a remote address for tests.')
diff --git a/au_test_harness/update_exception.py b/au_test_harness/update_exception.py
index 4c1e73e..432ce31 100644
--- a/au_test_harness/update_exception.py
+++ b/au_test_harness/update_exception.py
@@ -6,6 +6,7 @@
class UpdateException(Exception):
"""Exception thrown when _UpdateImage or _UpdateUsingPayload fail"""
- def __init__(self, code, stdout):
+ def __init__(self, code, output):
+ super(UpdateException, self).__init__(output)
self.code = code
- self.stdout = stdout
+ self.output = output
diff --git a/au_test_harness/vm_au_worker.py b/au_test_harness/vm_au_worker.py
index f64515e..d3113f2 100644
--- a/au_test_harness/vm_au_worker.py
+++ b/au_test_harness/vm_au_worker.py
@@ -17,7 +17,7 @@
def __init__(self, options, test_results_root):
"""Processes vm-specific options."""
- au_worker.AUWorker.__init__(self, options, test_results_root)
+ super(VMAUWorker, self).__init__(options, test_results_root)
self.graphics_flag = ''
if options.no_graphics: self.graphics_flag = '--no_graphics'
if not self.board: cros_lib.Die('Need board to convert base image to vm.')
@@ -25,10 +25,8 @@
def _KillExistingVM(self, pid_file):
"""Kills an existing VM specified by the pid_file."""
if os.path.exists(pid_file):
- cros_lib.Warning('Existing %s found. Deleting and killing process' %
- pid_file)
cros_lib.RunCommand(['./cros_stop_vm', '--kvm_pid=%s' % pid_file],
- cwd=self.crosutilsbin)
+ cwd=self.crosutilsbin, print_cmd=False)
assert not os.path.exists(pid_file)
@@ -61,6 +59,8 @@
]
self.AppendUpdateFlags(cmd, image_path, src_image_path, proxy_port,
private_key_path)
+ self.TestInfo(self.GetUpdateMessage(image_path, src_image_path, True,
+ proxy_port))
self.RunUpdateCmd(cmd, log_directory)
def UpdateUsingPayload(self, update_path, stateful_change='old',
@@ -80,6 +80,8 @@
stateful_change_flag,
]
if proxy_port: cmd.append('--proxy_port=%s' % proxy_port)
+ self.TestInfo(self.GetUpdateMessage(image_path, src_image_path, True,
+ proxy_port))
self.RunUpdateCmd(cmd, log_directory)
def VerifyImage(self, unittest, percent_required_to_pass=100):
@@ -98,9 +100,11 @@
self.verify_suite,
]
if self.graphics_flag: commandWithArgs.append(self.graphics_flag)
- output = cros_lib.RunCommand(commandWithArgs, error_ok=True,
- enter_chroot=False, redirect_stdout=True,
- cwd=self.crosutilsbin)
+ self.TestInfo('Running smoke suite to verify image.')
+ output = cros_lib.RunCommand(
+ commandWithArgs, error_ok=True, enter_chroot=False,
+ redirect_stdout=True, redirect_stderr=True, cwd=self.crosutilsbin,
+ print_cmd=False, combine_stdout_stderr=True)
return self.AssertEnoughTestsPassed(unittest, output,
percent_required_to_pass)
