centralize logging into root logger

If we setup root logger correctly and have each
module logger propogate we shouldn't need individual
logger configuration

updates:
    lower paramiko to WARN level
    dispatcher/file.py was missing logging.handlers import
    purge all existing handlers and add our own handlers
    move everything back into yardstick/__init__.py so API can use it
    make _LOG_STREAM_HDLR global, so we can set loglevel on it whenever
    added api/server.py call to _init_logging
    removed old LOG_FORMATTER from cli.py
    only setLevel on yardstick logger

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

5 files changed, 56 insertions, 21 deletions

diff --git a/api/server.py b/api/server.py
index 1cbe1725d..3f104c61a 100644
--- a/api/server.py
+++ b/api/server.py
@@ -12,6 +12,7 @@ from flask import Flask
 from flask_restful import Api
 
 from api.urls import urlpatterns
+from yardstick import _init_logging
 
 logger = logging.getLogger(__name__)
 
@@ -23,5 +24,7 @@ reduce(lambda a, b: a.add_resource(b.resource, b.url,
                                    endpoint=b.endpoint) or a, urlpatterns, api)
 
 if __name__ == '__main__':
+    _init_logging()
+    logger.setLevel(logging.DEBUG)
     logger.info('Starting server')
     app.run(host='0.0.0.0')
diff --git a/yardstick/__init__.py b/yardstick/__init__.py
index c31948d43..5c279c800 100644
--- a/yardstick/__init__.py
+++ b/yardstick/__init__.py
@@ -8,18 +8,40 @@
 ##############################################################################
 
 import logging
-import logging.config
-import sys
 import os
+import sys
+
 import yardstick.vTC.apexlake as apexlake
 
 # Hack to be able to run apexlake unit tests
 # without having to install apexlake.
 sys.path.append(os.path.dirname(apexlake.__file__))
 
-logging.basicConfig(
-    level=logging.WARNING,
-    format='[%(asctime)s] %(name)-20s %(filename)s:%(lineno)d '
-        '%(levelname)s %(message)s',  # noqa
-    datefmt='%m/%d/%y %H:%M:%S')
-logging.getLogger(__name__).setLevel(logging.INFO)
+LOG_FILE = '/tmp/yardstick.log'
+LOG_FORMATTER = ('%(asctime)s '
+                 '%(name)s %(filename)s:%(lineno)d '
+                 '%(levelname)s %(message)s')
+
+_LOG_FORMATTER = logging.Formatter(LOG_FORMATTER)
+_LOG_STREAM_HDLR = logging.StreamHandler()
+_LOG_FILE_HDLR = logging.FileHandler(LOG_FILE)
+
+LOG = logging.getLogger(__name__)
+
+
+def _init_logging():
+
+    _LOG_STREAM_HDLR.setFormatter(_LOG_FORMATTER)
+
+    # don't append to log file, clobber
+    _LOG_FILE_HDLR.setFormatter(_LOG_FORMATTER)
+
+    del logging.root.handlers[:]
+    logging.root.addHandler(_LOG_STREAM_HDLR)
+    logging.root.addHandler(_LOG_FILE_HDLR)
+    logging.debug("logging.root.handlers = %s", logging.root.handlers)
+
+    if os.environ.get('CI_DEBUG', '').lower() in {'1', 1, 'y', "yes", "true"}:
+        LOG.setLevel(logging.DEBUG)
+    else:
+        LOG.setLevel(logging.INFO)
diff --git a/yardstick/cmd/cli.py b/yardstick/cmd/cli.py
index d141731e1..cac3dc5bf 100644
--- a/yardstick/cmd/cli.py
+++ b/yardstick/cmd/cli.py
@@ -19,6 +19,7 @@ from pkg_resources import get_distribution
 from argparse import RawDescriptionHelpFormatter
 from oslo_config import cfg
 
+from yardstick import _init_logging, LOG
 from yardstick.cmd.commands import task
 from yardstick.cmd.commands import runner
 from yardstick.cmd.commands import scenario
@@ -129,15 +130,12 @@ class YardstickCLI():
 
     def _handle_global_opts(self):
 
-        # handle global opts
-        logger = logging.getLogger('yardstick')
-        logger.setLevel(logging.WARNING)
-
+        _init_logging()
         if CONF.verbose:
-            logger.setLevel(logging.INFO)
+            LOG.setLevel(logging.INFO)
 
         if CONF.debug:
-            logger.setLevel(logging.DEBUG)
+            LOG.setLevel(logging.DEBUG)
 
     def _dispath_func_notask(self):
 
diff --git a/yardstick/dispatcher/file.py b/yardstick/dispatcher/file.py
index ab67796e9..c2cc265ba 100644
--- a/yardstick/dispatcher/file.py
+++ b/yardstick/dispatcher/file.py
@@ -17,6 +17,7 @@
 # ceilometer/ceilometer/dispatcher/file.py
 
 import logging
+import logging.handlers
 import json
 
 from oslo_config import cfg
diff --git a/yardstick/ssh.py b/yardstick/ssh.py
index 8b71fe606..d287b4dac 100644
--- a/yardstick/ssh.py
+++ b/yardstick/ssh.py
@@ -57,17 +57,16 @@ Eventlet:
     sshclient = eventlet.import_patched("opentstack.common.sshclient")
 
 """
-
+import os
 import select
 import socket
 import time
 
+import logging
 import paramiko
 from scp import SCPClient
 import six
-import logging
 
-LOG = logging.getLogger(__name__)
 
 DEFAULT_PORT = 22
 
@@ -84,7 +83,7 @@ class SSH(object):
     """Represent ssh connection."""
 
     def __init__(self, user, host, port=DEFAULT_PORT, pkey=None,
-                 key_filename=None, password=None):
+                 key_filename=None, password=None, name=None):
         """Initialize SSH client.
 
         :param user: ssh username
@@ -94,6 +93,11 @@ class SSH(object):
         :param key_filename: private key filename
         :param password: password
         """
+        self.name = name
+        if name:
+            self.log = logging.getLogger(__name__ + '.' + self.name)
+        else:
+            self.log = logging.getLogger(__name__)
 
         self.user = user
         self.host = host
@@ -103,6 +107,13 @@ class SSH(object):
         self.password = password
         self.key_filename = key_filename
         self._client = False
+        # paramiko loglevel debug will output ssh protocl debug
+        # we don't ever really want that unless we are debugging paramiko
+        # ssh issues
+        if os.environ.get("PARAMIKO_DEBUG", "").lower() == "true":
+            logging.getLogger("paramiko").setLevel(logging.DEBUG)
+        else:
+            logging.getLogger("paramiko").setLevel(logging.WARN)
 
     def _get_pkey(self, key):
         if isinstance(key, six.string_types):
@@ -186,14 +197,14 @@ class SSH(object):
 
             if session.recv_ready():
                 data = session.recv(4096)
-                LOG.debug("stdout: %r" % data)
+                self.log.debug("stdout: %r" % data)
                 if stdout is not None:
                     stdout.write(data)
                 continue
 
             if session.recv_stderr_ready():
                 stderr_data = session.recv_stderr(4096)
-                LOG.debug("stderr: %r" % stderr_data)
+                self.log.debug("stderr: %r" % stderr_data)
                 if stderr is not None:
                     stderr.write(stderr_data)
                 continue
@@ -256,7 +267,7 @@ class SSH(object):
             try:
                 return self.execute("uname")
             except (socket.error, SSHError) as e:
-                LOG.debug("Ssh is still unavailable: %r" % e)
+                self.log.debug("Ssh is still unavailable: %r" % e)
                 time.sleep(interval)
             if time.time() > (start_time + timeout):
                 raise SSHTimeout("Timeout waiting for '%s'" % self.host)