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/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):