autotest: add logging in testing control files.
This CL adds more loggings for running tests by control files.
BUG=chromium:674598
TEST=Run autoupdate_End_to_End test in local AFE and verify loggings.
Change-Id: I7c6696d2d46c8e2eff9dc744f9be53fa6045f5f1
Reviewed-on: https://chromium-review.googlesource.com/435964
Commit-Ready: Xixuan Wu <xixuan@chromium.org>
Tested-by: Xixuan Wu <xixuan@chromium.org>
Reviewed-by: Luigi Semenzato <semenzato@chromium.org>
diff --git a/client/common_lib/test.py b/client/common_lib/test.py
index 934a91f..b7602a2 100644
--- a/client/common_lib/test.py
+++ b/client/common_lib/test.py
@@ -359,8 +359,10 @@
postprocess_profiled_run, args, dargs):
self.drop_caches_between_iterations()
# execute iteration hooks
+ logging.debug('starting before_iteration_hooks')
for hook in self.before_iteration_hooks:
hook(self)
+ logging.debug('before_iteration_hooks completed')
try:
if profile_only:
@@ -373,17 +375,24 @@
*args, **dargs)
else:
self.before_run_once()
+ logging.debug('starting test(run_once()), test details follow'
+ '\n%r', args)
self.run_once(*args, **dargs)
+ logging.debug('The test has completed successfully')
self.after_run_once()
self.postprocess_iteration()
self.analyze_perf_constraints(constraints)
# Catch and re-raise to let after_iteration_hooks see the exception.
- except:
+ except Exception as e:
+ logging.debug('Test failed due to %s. Exception log follows the '
+ 'after_iteration_hooks.', str(e))
raise
finally:
+ logging.debug('starting after_iteration_hooks')
for hook in reversed(self.after_iteration_hooks):
hook(self)
+ logging.debug('after_iteration_hooks completed')
def execute(self, iterations=None, test_length=None, profile_only=None,
@@ -602,12 +611,13 @@
# Save the exception while we run our cleanup() before
# reraising it, but log it to so actual time of error is known.
exc_info = sys.exc_info()
- logging.warning('Autotest caught exception when running test:',
+ logging.warning('The test failed with the following exception',
exc_info=True)
try:
try:
if run_cleanup:
+ logging.debug('Running cleanup for test.')
_cherry_pick_call(self.cleanup, *args, **dargs)
except Exception:
logging.error('Ignoring exception during cleanup() '
@@ -617,6 +627,9 @@
exc_info[0])
self.crash_handler_report()
finally:
+ # Raise exception after running cleanup, reporting crash,
+ # and restoring job's logging, even if the first two
+ # actions fail.
self.job.logging.restore()
try:
raise exc_info[0], exc_info[1], exc_info[2]
diff --git a/server/autotest.py b/server/autotest.py
index 3dd5ce4..45fa374 100644
--- a/server/autotest.py
+++ b/server/autotest.py
@@ -366,6 +366,8 @@
the control file.
"""
host = self._get_host_and_setup(host, use_packaging=use_packaging)
+ logging.debug('Autotest job starts on remote host: %s',
+ host.hostname)
results_dir = os.path.abspath(results_dir)
if client_disconnect_timeout is None:
@@ -941,6 +943,8 @@
"client on %s: %s\n") % (self.host.hostname, last)
raise error.AutotestRunError(msg)
finally:
+ logging.debug('Autotest job finishes running. Below is the '
+ 'post-processing operations.')
logger.close()
if not self.background:
collector.collect_client_job_results()
@@ -953,6 +957,8 @@
local_results)
job_record_context.restore()
+ logging.debug('Autotest job finishes.')
+
# should only get here if we timed out
assert timeout
raise error.AutotestTimeoutError()
diff --git a/server/test.py b/server/test.py
index 6af056b..e9aa96a 100644
--- a/server/test.py
+++ b/server/test.py
@@ -175,10 +175,12 @@
@install_autotest_and_run
def before_hook(self, mytest, host, at, outputdir):
# run the pre-test sysinfo script
+ logging.debug('before_hook starts running for test %r.', mytest)
at.run(_sysinfo_before_test_script % outputdir,
results_dir=self.job.resultdir)
self._pull_pickle(host, outputdir)
+ logging.debug('before_hook ends running.')
@log.log_and_ignore_errors("pre-test iteration server sysinfo error:")
@@ -186,6 +188,8 @@
def before_iteration_hook(self, mytest, host, at, outputdir):
# this function is called after before_hook() se we have sysinfo state
# to push to the server
+ logging.debug('before_iteration_hook starts running for test %r.',
+ mytest)
self._push_pickle(host, outputdir);
# run the pre-test iteration sysinfo script
at.run(_sysinfo_iteration_script %
@@ -195,12 +199,15 @@
# get the new sysinfo state from the client
self._pull_pickle(host, outputdir)
+ logging.debug('before_iteration_hook ends running.')
@log.log_and_ignore_errors("post-test iteration server sysinfo error:")
@install_autotest_and_run
def after_iteration_hook(self, mytest, host, at, outputdir):
# push latest sysinfo state to the client
+ logging.debug('after_iteration_hook starts running for test %r.',
+ mytest)
self._push_pickle(host, outputdir);
# run the post-test iteration sysinfo script
at.run(_sysinfo_iteration_script %
@@ -210,17 +217,20 @@
# get the new sysinfo state from the client
self._pull_pickle(host, outputdir)
+ logging.debug('after_iteration_hook ends running.')
@log.log_and_ignore_errors("post-test server sysinfo error:")
@install_autotest_and_run
def after_hook(self, mytest, host, at, outputdir):
+ logging.debug('after_hook starts running for test %r.', mytest)
self._push_pickle(host, outputdir);
# run the post-test sysinfo script
at.run(_sysinfo_after_test_script % (outputdir, mytest.success),
results_dir=self.job.resultdir)
self._pull_sysinfo_keyval(host, outputdir, mytest)
+ logging.debug('after_hook ends running.')
def cleanup(self, host_close=True):
