Merge "improve logging, clear using print"

9 files changed, 40 insertions, 43 deletions

diff --git a/yardstick/__init__.py b/yardstick/__init__.py
index c1010d98c..b673e7c4a 100644
--- a/yardstick/__init__.py
+++ b/yardstick/__init__.py
@@ -16,9 +16,7 @@ from yardstick.common import utils as yardstick_utils
 
 yardstick_utils.makedirs(constants.LOG_DIR)
 LOG_FILE = os.path.join(constants.LOG_DIR, 'yardstick.log')
-LOG_FORMATTER = ('%(asctime)s '
-                 '%(name)s %(filename)s:%(lineno)d '
-                 '%(levelname)s %(message)s')
+LOG_FORMATTER = '%(asctime)s [%(levelname)s] %(name)s %(filename)s:%(lineno)d %(message)s'
 
 _LOG_FORMATTER = logging.Formatter(LOG_FORMATTER)
 _LOG_STREAM_HDLR = logging.StreamHandler()
diff --git a/yardstick/benchmark/contexts/heat.py b/yardstick/benchmark/contexts/heat.py
index 94a3824a7..d2309cc10 100644
--- a/yardstick/benchmark/contexts/heat.py
+++ b/yardstick/benchmark/contexts/heat.py
@@ -295,7 +295,7 @@ class HeatContext(Context):
 
     def deploy(self):
         """deploys template into a stack using cloud"""
-        print("Deploying context '%s'" % self.name)
+        LOG.info("Deploying context '%s' START", self.name)
 
         heat_template = HeatTemplate(self.name, self.template_file,
                                      self.heat_parameters)
@@ -325,7 +325,7 @@ class HeatContext(Context):
                 server.public_ip = \
                     self.stack.outputs[server.floating_ip["stack_name"]]
 
-        print("Context '%s' deployed" % self.name)
+        LOG.info("Deploying context '%s' DONE", self.name)
 
     def add_server_port(self, server):
         # TODO(hafe) can only handle one internal network for now
@@ -370,10 +370,10 @@ class HeatContext(Context):
     def undeploy(self):
         """undeploys stack from cloud"""
         if self.stack:
-            print("Undeploying context '%s'" % self.name)
+            LOG.info("Undeploying context '%s' START", self.name)
             self.stack.delete()
             self.stack = None
-            print("Context '%s' undeployed" % self.name)
+            LOG.info("Undeploying context '%s' DONE", self.name)
 
         if os.path.exists(self.key_filename):
             try:
diff --git a/yardstick/benchmark/core/plugin.py b/yardstick/benchmark/core/plugin.py
index 24f1b6b25..56ecd29d9 100644
--- a/yardstick/benchmark/core/plugin.py
+++ b/yardstick/benchmark/core/plugin.py
@@ -38,19 +38,19 @@ class Plugin(object):
 
         plugins, deployment = parser.parse_plugin()
         plugin_name = plugins.get("name")
-        print("Installing plugin: %s" % plugin_name)
+        LOG.info("Installing plugin: %s", plugin_name)
 
-        LOG.info("Executing _install_setup()")
+        LOG.debug("Executing _install_setup()")
         self._install_setup(plugin_name, deployment)
 
-        LOG.info("Executing _run()")
+        LOG.debug("Executing _run()")
         self._run(plugin_name)
 
         total_end_time = time.time()
-        LOG.info("total finished in %d secs",
+        LOG.info("Total finished in %d secs",
                  total_end_time - total_start_time)
 
-        print("Done, exiting")
+        LOG.info("Plugin %s Done, exiting", plugin_name)
 
     def remove(self, args):
         """Remove a plugin."""
diff --git a/yardstick/benchmark/core/task.py b/yardstick/benchmark/core/task.py
index 29295537a..a8447e2cf 100644
--- a/yardstick/benchmark/core/task.py
+++ b/yardstick/benchmark/core/task.py
@@ -97,8 +97,8 @@ class Task(object):     # pragma: no cover
             task_args = [args.task_args]
             task_args_fnames = [args.task_args_file]
 
-        LOG.info("\ntask_files:%s, \ntask_args:%s, \ntask_args_fnames:%s",
-                 task_files, task_args, task_args_fnames)
+        LOG.debug("task_files:%s, task_args:%s, task_args_fnames:%s",
+                  task_files, task_args, task_args_fnames)
 
         if args.parse_only:
             sys.exit(0)
@@ -139,7 +139,7 @@ class Task(object):     # pragma: no cover
                     context.undeploy()
                 self.contexts = []
             one_task_end_time = time.time()
-            LOG.info("task %s finished in %d secs", task_files[i],
+            LOG.info("Task %s finished in %d secs", task_files[i],
                      one_task_end_time - one_task_start_time)
 
         result = self._get_format_result(testcases)
@@ -148,14 +148,13 @@ class Task(object):     # pragma: no cover
         self._generate_reporting(result)
 
         total_end_time = time.time()
-        LOG.info("total finished in %d secs",
+        LOG.info("Total finished in %d secs",
                  total_end_time - total_start_time)
 
         scenario = scenarios[0]
-        print("To generate report execute => yardstick report generate ",
-              scenario['task_id'], scenario['tc'])
-
-        print("Done, exiting")
+        LOG.info("To generate report, execute command "
+                 "'yardstick report generate %(task_id)s %(tc)s'", scenario)
+        LOG.info("Task ALL DONE, exiting")
         return result
 
     def _generate_reporting(self, result):
@@ -163,7 +162,7 @@ class Task(object):     # pragma: no cover
         with open(constants.REPORTING_FILE, 'w') as f:
             f.write(env.from_string(report_template).render(result))
 
-        LOG.info('yardstick reporting generate in %s', constants.REPORTING_FILE)
+        LOG.info("Report can be found in '%s'", constants.REPORTING_FILE)
 
     def _set_log(self):
         log_format = '%(asctime)s %(name)s %(filename)s:%(lineno)d %(levelname)s %(message)s'
@@ -265,7 +264,7 @@ class Task(object):     # pragma: no cover
                     raise RuntimeError
                 self.outputs.update(runner.get_output())
                 result.extend(runner.get_result())
-                print("Runner ended, output in", output_file)
+                LOG.info("Runner ended, output in %s", output_file)
         else:
             # run serially
             for scenario in scenarios:
@@ -277,7 +276,7 @@ class Task(object):     # pragma: no cover
                         raise RuntimeError
                     self.outputs.update(runner.get_output())
                     result.extend(runner.get_result())
-                    print("Runner ended, output in", output_file)
+                    LOG.info("Runner ended, output in %s", output_file)
 
         # Abort background runners
         for runner in background_runners:
@@ -302,7 +301,7 @@ class Task(object):     # pragma: no cover
         base_runner.Runner.terminate_all()
 
         if self.contexts:
-            print("Undeploying all contexts")
+            LOG.info("Undeploying all contexts")
             for context in self.contexts[::-1]:
                 context.undeploy()
 
@@ -365,7 +364,7 @@ class Task(object):     # pragma: no cover
                 context_cfg["nodes"])
         runner = base_runner.Runner.get(runner_cfg)
 
-        print("Starting runner of type '%s'" % runner_cfg["type"])
+        LOG.info("Starting runner of type '%s'", runner_cfg["type"])
         runner.run(scenario_cfg, context_cfg)
 
         return runner
@@ -475,7 +474,7 @@ class TaskParser(object):       # pragma: no cover
 
     def parse_task(self, task_id, task_args=None, task_args_file=None):
         """parses the task file and return an context and scenario instances"""
-        print("Parsing task config:", self.path)
+        LOG.info("Parsing task config: %s", self.path)
 
         try:
             kw = {}
@@ -492,10 +491,9 @@ class TaskParser(object):       # pragma: no cover
                     input_task = f.read()
                     rendered_task = TaskTemplate.render(input_task, **kw)
                 except Exception as e:
-                    print("Failed to render template:\n%(task)s\n%(err)s\n"
-                          % {"task": input_task, "err": e})
+                    LOG.exception('Failed to render template:\n%s\n', input_task)
                     raise e
-                print("Input task is:\n%s\n" % rendered_task)
+                LOG.debug("Input task is:\n%s\n", rendered_task)
 
                 cfg = yaml_load(rendered_task)
         except IOError as ioerror:
diff --git a/yardstick/benchmark/runners/duration.py b/yardstick/benchmark/runners/duration.py
index 69d744562..c2c6a8f19 100644
--- a/yardstick/benchmark/runners/duration.py
+++ b/yardstick/benchmark/runners/duration.py
@@ -40,7 +40,8 @@ def _worker_process(queue, cls, method_name, scenario_cfg,
 
     interval = runner_cfg.get("interval", 1)
     duration = runner_cfg.get("duration", 60)
-    LOG.info("worker START, duration %d sec, class %s", duration, cls)
+    LOG.info("Worker START, duration is %ds", duration)
+    LOG.debug("class is %s", cls)
 
     runner_cfg['runner_id'] = os.getpid()
 
@@ -95,7 +96,7 @@ def _worker_process(queue, cls, method_name, scenario_cfg,
 
         if (errors and sla_action is None) or \
                 (time.time() - start > duration or aborted.is_set()):
-            LOG.info("worker END")
+            LOG.info("Worker END")
             break
 
     benchmark.teardown()
diff --git a/yardstick/benchmark/scenarios/lib/create_keypair.py b/yardstick/benchmark/scenarios/lib/create_keypair.py
index 2185bfa5d..f5b1fff7a 100644
--- a/yardstick/benchmark/scenarios/lib/create_keypair.py
+++ b/yardstick/benchmark/scenarios/lib/create_keypair.py
@@ -47,7 +47,7 @@ class CreateKeypair(base.Scenario):
 
         rsa_key = paramiko.RSAKey.generate(bits=2048, progress_func=None)
         rsa_key.write_private_key_file(self.key_filename)
-        print("Writing %s ..." % self.key_filename)
+        LOG.info("Writing key_file %s ...", self.key_filename)
         with open(self.key_filename + ".pub", "w") as pubkey_file:
             pubkey_file.write(
                 "%s %s\n" % (rsa_key.get_name(), rsa_key.get_base64()))
diff --git a/yardstick/benchmark/scenarios/networking/ping.py b/yardstick/benchmark/scenarios/networking/ping.py
index 6a7927de4..3bade73e2 100644
--- a/yardstick/benchmark/scenarios/networking/ping.py
+++ b/yardstick/benchmark/scenarios/networking/ping.py
@@ -67,7 +67,7 @@ class Ping(base.Scenario):
             else:
                 target_vm = self.scenario_cfg['target']
 
-            LOG.debug("ping '%s' '%s'", options, dest)
+            LOG.debug("ping %s %s", options, dest)
             with open(self.target_script, "r") as stdin_file:
                 exit_status, stdout, stderr = self.connection.execute(
                     "/bin/sh -s {0} {1}".format(dest, options),
diff --git a/yardstick/cmd/commands/task.py b/yardstick/cmd/commands/task.py
index bd5447836..e2e8bf67d 100644
--- a/yardstick/cmd/commands/task.py
+++ b/yardstick/cmd/commands/task.py
@@ -51,7 +51,7 @@ class TaskCommands(object):     # pragma: no cover
         self.output_file = param.output_file
 
         result = {}
-
+        LOG.info('Task START')
         try:
             result = Task().start(param, **kwargs)
         except Exception as e:
@@ -59,9 +59,9 @@ class TaskCommands(object):     # pragma: no cover
             LOG.exception("")
 
         if result.get('result', {}).get('criteria') == 'PASS':
-            LOG.info('Task Success')
+            LOG.info('Task SUCCESS')
         else:
-            LOG.info('Task Failed')
+            LOG.info('Task FAILED')
             raise RuntimeError('Task Failed')
 
     def _write_error_data(self, error):
diff --git a/yardstick/orchestrator/heat.py b/yardstick/orchestrator/heat.py
index 8c7b1e429..455ddc34e 100644
--- a/yardstick/orchestrator/heat.py
+++ b/yardstick/orchestrator/heat.py
@@ -89,14 +89,14 @@ class HeatStack(HeatObject):
         if self.uuid is None:
             return
 
-        log.info("Deleting stack '%s', uuid:%s", self.name, self.uuid)
+        log.info("Deleting stack '%s' START, uuid:%s", self.name, self.uuid)
         heat = self.heat_client
         template = heat.stacks.get(self.uuid)
         start_time = time.time()
         template.delete()
 
         for status in iter(self.status, u'DELETE_COMPLETE'):
-            log.debug("stack state %s", status)
+            log.debug("Deleting stack state: %s", status)
             if status == u'DELETE_FAILED':
                 raise RuntimeError(
                     heat.stacks.get(self.uuid).stack_status_reason)
@@ -104,7 +104,7 @@ class HeatStack(HeatObject):
             time.sleep(2)
 
         end_time = time.time()
-        log.info("Deleted stack '%s' in %d secs", self.name,
+        log.info("Deleting stack '%s' DONE in %d secs", self.name,
                  end_time - start_time)
         self.uuid = None
 
@@ -599,7 +599,7 @@ name (i.e. %s).\
         :param: timeout: timeout in seconds for Heat create, default 3600s
         :type timeout: int
         """
-        log.info("Creating stack '%s'", self.name)
+        log.info("Creating stack '%s' START", self.name)
 
         # create stack early to support cleanup, e.g. ctrl-c while waiting
         stack = HeatStack(self.name)
@@ -613,13 +613,13 @@ name (i.e. %s).\
         if not block:
             self.outputs = stack.outputs = {}
             end_time = time.time()
-            log.info("Created stack '%s' in %.3e secs",
+            log.info("Creating stack '%s' DONE in %d secs",
                      self.name, end_time - start_time)
             return stack
 
         time_limit = start_time + timeout
         for status in iter(self.status, self.HEAT_CREATE_COMPLETE_STATUS):
-            log.debug("stack state %s", status)
+            log.debug("Creating stack state: %s", status)
             if status == u'CREATE_FAILED':
                 stack_status_reason = heat_client.stacks.get(self.uuid).stack_status_reason
                 heat_client.stacks.delete(self.uuid)
@@ -631,7 +631,7 @@ name (i.e. %s).\
 
         end_time = time.time()
         outputs = heat_client.stacks.get(self.uuid).outputs
-        log.info("Created stack '%s' in %.3e secs",
+        log.info("Creating stack '%s' DONE in %d secs",
                  self.name, end_time - start_time)
 
         # keep outputs as unicode