switch logging to proper usage

The logging methods do string interpolation themselves

From the reference:

https://docs.python.org/2/library/logging.html#logging.Logger.debug

  Logger.debug(msg, *args, **kwargs)

Logs a message with level DEBUG on this logger. The msg is the message format string, and the args are the arguments which are merged into msg using the string formatting operator. (Note that this means that you can use keywords in the format string, together with a single dictionary argument.)

There are two keyword arguments in kwargs which are inspected: exc_info which, if it does not evaluate as false, causes exception information to be added to the logging message. If an exception tuple (in the format returned by sys.exc_info()) is provided, it is used; otherwise, sys.exc_info() is called to get the exception informatio

The reason logging does string interpolation itselfs is to implement deferred interpolation.

String interpolation involves evaluating arguments, so it can introduce significant computation.  The logging module tries to be smart about deferring interpolation until the last possible moment.

The logging methods check isEnabledFor for the log level and won't interpolate if the level is not enabled.

https://github.com/python/cpython/blob/2.7/Lib/logging/__init__.py#L1178

     def warning(self, msg, *args, **kwargs):
        if self.isEnabledFor(WARNING):
            self._log(WARNING, msg, args, **kwargs)

logging actually waits to interpolate the string in LogRecord.getMessage()

https://github.com/python/cpython/blob/2.7/Lib/logging/__init__.py#L328
        if self.args:
            msg = msg % self.args

Change-Id: Ie09efe0a66881e19bd8119caa376075e605627a2
Signed-off-by: Ross Brattain <ross.b.brattain@intel.com>

5 files changed, 21 insertions, 21 deletions

diff --git a/yardstick/benchmark/runners/arithmetic.py b/yardstick/benchmark/runners/arithmetic.py
index 74a236f44..69ea915a1 100755
--- a/yardstick/benchmark/runners/arithmetic.py
+++ b/yardstick/benchmark/runners/arithmetic.py
@@ -93,7 +93,7 @@ def _worker_process(queue, cls, method_name, scenario_cfg,
         if aborted.is_set():
             break
 
-        LOG.debug("runner=%(runner)s seq=%(sequence)s START" %
+        LOG.debug("runner=%(runner)s seq=%(sequence)s START",
                   {"runner": runner_cfg["runner_id"], "sequence": sequence})
 
         for i, value in enumerate(comb_values):
@@ -109,7 +109,7 @@ def _worker_process(queue, cls, method_name, scenario_cfg,
             if sla_action == "assert":
                 raise
             elif sla_action == "monitor":
-                LOG.warning("SLA validation failed: %s" % assertion.args)
+                LOG.warning("SLA validation failed: %s", assertion.args)
                 errors = assertion.args
         except Exception as e:
             errors = traceback.format_exc()
@@ -129,7 +129,7 @@ def _worker_process(queue, cls, method_name, scenario_cfg,
 
         queue.put(record)
 
-        LOG.debug("runner=%(runner)s seq=%(sequence)s END" %
+        LOG.debug("runner=%(runner)s seq=%(sequence)s END",
                   {"runner": runner_cfg["runner_id"], "sequence": sequence})
 
         sequence += 1
diff --git a/yardstick/benchmark/runners/base.py b/yardstick/benchmark/runners/base.py
index 23749924f..8f3f75fa1 100755
--- a/yardstick/benchmark/runners/base.py
+++ b/yardstick/benchmark/runners/base.py
@@ -63,7 +63,7 @@ def _execute_shell_command(command):
     except Exception:
         exitcode = -1
         output = traceback.format_exc()
-        log.error("exec command '%s' error:\n " % command)
+        log.error("exec command '%s' error:\n ", command)
         log.error(traceback.format_exc())
 
     return exitcode, output
@@ -76,10 +76,10 @@ def _single_action(seconds, command, queue):
     log.debug("single action: executing command: '%s'", command)
     ret_code, data = _execute_shell_command(command)
     if ret_code < 0:
-        log.error("single action error! command:%s" % command)
+        log.error("single action error! command:%s", command)
         queue.put({'single-action-data': data})
         return
-    log.debug("single action data: \n%s" % data)
+    log.debug("single action data: \n%s", data)
     queue.put({'single-action-data': data})
 
 
@@ -96,7 +96,7 @@ def _periodic_action(interval, command, queue):
             log.error("periodic action error! command:%s", command)
             queue.put({'periodic-action-data': data})
             break
-        log.debug("periodic action data: \n%s" % data)
+        log.debug("periodic action data: \n%s", data)
         queue.put({'periodic-action-data': data})
 
 
@@ -127,7 +127,7 @@ class Runner(object):
         """
         # if there is no runner, start the output serializer subprocess
         if len(Runner.runners) == 0:
-            log.debug("Starting dump process file '%s'" %
+            log.debug("Starting dump process file '%s'",
                       config["output_filename"])
             Runner.queue = multiprocessing.Queue()
             Runner.dump_process = multiprocessing.Process(
@@ -196,13 +196,13 @@ class Runner(object):
         '''run a potentially configured post-stop action'''
         if "post-stop-action" in self.config:
             command = self.config["post-stop-action"]["command"]
-            log.debug("post stop action: command: '%s'" % command)
+            log.debug("post stop action: command: '%s'", command)
             ret_code, data = _execute_shell_command(command)
             if ret_code < 0:
                 log.error("post action error! command:%s", command)
                 self.result_queue.put({'post-stop-action-data': data})
                 return
-            log.debug("post-stop data: \n%s" % data)
+            log.debug("post-stop data: \n%s", data)
             self.result_queue.put({'post-stop-action-data': data})
 
     def run(self, scenario_cfg, context_cfg):
@@ -219,13 +219,13 @@ class Runner(object):
         # run a potentially configured pre-start action
         if "pre-start-action" in self.config:
             command = self.config["pre-start-action"]["command"]
-            log.debug("pre start action: command: '%s'" % command)
+            log.debug("pre start action: command: '%s'", command)
             ret_code, data = _execute_shell_command(command)
             if ret_code < 0:
                 log.error("pre-start action error! command:%s", command)
                 self.result_queue.put({'pre-start-action-data': data})
                 return
-            log.debug("pre-start data: \n%s" % data)
+            log.debug("pre-start data: \n%s", data)
             self.result_queue.put({'pre-start-action-data': data})
 
         if "single-shot-action" in self.config:
diff --git a/yardstick/benchmark/runners/duration.py b/yardstick/benchmark/runners/duration.py
index 1f51f513f..1412c0caa 100644
--- a/yardstick/benchmark/runners/duration.py
+++ b/yardstick/benchmark/runners/duration.py
@@ -58,7 +58,7 @@ def _worker_process(queue, cls, method_name, scenario_cfg,
     start = time.time()
     while True:
 
-        LOG.debug("runner=%(runner)s seq=%(sequence)s START" %
+        LOG.debug("runner=%(runner)s seq=%(sequence)s START",
                   {"runner": runner_cfg["runner_id"], "sequence": sequence})
 
         data = {}
@@ -71,7 +71,7 @@ def _worker_process(queue, cls, method_name, scenario_cfg,
             if sla_action == "assert":
                 raise
             elif sla_action == "monitor":
-                LOG.warning("SLA validation failed: %s" % assertion.args)
+                LOG.warning("SLA validation failed: %s", assertion.args)
                 errors = assertion.args
         except Exception as e:
             errors = traceback.format_exc()
@@ -91,7 +91,7 @@ def _worker_process(queue, cls, method_name, scenario_cfg,
 
         queue.put(record)
 
-        LOG.debug("runner=%(runner)s seq=%(sequence)s END" %
+        LOG.debug("runner=%(runner)s seq=%(sequence)s END",
                   {"runner": runner_cfg["runner_id"], "sequence": sequence})
 
         sequence += 1
diff --git a/yardstick/benchmark/runners/iteration.py b/yardstick/benchmark/runners/iteration.py
index b23b32b08..3a839b65f 100644
--- a/yardstick/benchmark/runners/iteration.py
+++ b/yardstick/benchmark/runners/iteration.py
@@ -60,7 +60,7 @@ def _worker_process(queue, cls, method_name, scenario_cfg,
     if "run" in run_step:
         while True:
 
-            LOG.debug("runner=%(runner)s seq=%(sequence)s START" %
+            LOG.debug("runner=%(runner)s seq=%(sequence)s START",
                       {"runner": runner_cfg["runner_id"],
                        "sequence": sequence})
 
@@ -74,7 +74,7 @@ def _worker_process(queue, cls, method_name, scenario_cfg,
                 if sla_action == "assert":
                     raise
                 elif sla_action == "monitor":
-                    LOG.warning("SLA validation failed: %s" % assertion.args)
+                    LOG.warning("SLA validation failed: %s", assertion.args)
                     errors = assertion.args
             except Exception as e:
                 errors = traceback.format_exc()
@@ -94,7 +94,7 @@ def _worker_process(queue, cls, method_name, scenario_cfg,
 
             queue.put(record)
 
-            LOG.debug("runner=%(runner)s seq=%(sequence)s END" %
+            LOG.debug("runner=%(runner)s seq=%(sequence)s END",
                       {"runner": runner_cfg["runner_id"],
                        "sequence": sequence})
 
diff --git a/yardstick/benchmark/runners/sequence.py b/yardstick/benchmark/runners/sequence.py
index fe53412ca..3b06e2a36 100644
--- a/yardstick/benchmark/runners/sequence.py
+++ b/yardstick/benchmark/runners/sequence.py
@@ -67,7 +67,7 @@ def _worker_process(queue, cls, method_name, scenario_cfg,
     for value in sequence_values:
         options[arg_name] = value
 
-        LOG.debug("runner=%(runner)s seq=%(sequence)s START" %
+        LOG.debug("runner=%(runner)s seq=%(sequence)s START",
                   {"runner": runner_cfg["runner_id"], "sequence": sequence})
 
         data = {}
@@ -80,7 +80,7 @@ def _worker_process(queue, cls, method_name, scenario_cfg,
             if sla_action == "assert":
                 raise
             elif sla_action == "monitor":
-                LOG.warning("SLA validation failed: %s" % assertion.args)
+                LOG.warning("SLA validation failed: %s", assertion.args)
                 errors = assertion.args
         except Exception as e:
             errors = traceback.format_exc()
@@ -100,7 +100,7 @@ def _worker_process(queue, cls, method_name, scenario_cfg,
 
         queue.put(record)
 
-        LOG.debug("runner=%(runner)s seq=%(sequence)s END" %
+        LOG.debug("runner=%(runner)s seq=%(sequence)s END",
                   {"runner": runner_cfg["runner_id"], "sequence": sequence})
 
         sequence += 1