Updates to Tests/Testing

Improve logging, error handling, messaging, and overall
functionality.

- Added '--only' as option as well as '-O' flag to select test
  suites (for consistency with other flags)
- Updated tracer to pop it's argument out of sys.argv (and
  refactored/optimized some code)
- Updated test cleanup so we can now run all suites in
  the same process (less messing about with Popen/Wait)
- Addressed many (handled) import errors showing up with new
  logging (many unnecessary in backend loader)
- Added logging along the way
- unittest.skip not working in test_middleware, so explicitely
  raised SkipTest exceptions
- Made test suites skip intelligently if test filter calls for
  client, functional, or unit tests
- Configured all suite config files to point to same log file
  to more easily debug when running multiple suites

bp keystone-logging

Change-Id: Ic05306c9b8e249c2cbcf92bda3c066031835901b

17 files changed, 288 insertions, 153 deletions

diff --git a/keystone/backends/sqlalchemy/__init__.py b/keystone/backends/sqlalchemy/__init__.py
index c4bd45c3..5e88c5ec 100755
--- a/keystone/backends/sqlalchemy/__init__.py
+++ b/keystone/backends/sqlalchemy/__init__.py
@@ -20,6 +20,7 @@ from sqlalchemy.orm import joinedload, aliased, sessionmaker
 
 import ast
 import logging
+import sys
 
 from sqlalchemy import create_engine
 from sqlalchemy.pool import StaticPool
@@ -35,10 +36,8 @@ from keystone.backends.sqlalchemy import migration
 import keystone.backends.api as top_api
 import keystone.backends.models as top_models
 
-
 logger = logging.getLogger(__name__)
 
-
 _DRIVER = None
 
 
@@ -98,23 +97,22 @@ class Driver():
 
     def _init_models(self, model_list):
         for model in model_list:
-            model_path = '.'.join([__package__, 'models', model])
-            module = utils.import_module(model_path)
-
-            top_models.set_value(model, module)
+            model_class = getattr(models, model)
+            top_models.set_value(model, model_class)
 
-            if module.__api__ is not None:
-                api_path = '.'.join([__package__, 'api', module.__api__])
-                api_module = utils.import_module(api_path)
-                top_api.set_value(module.__api__, api_module.get())
+            if model_class.__api__ is not None:
+                api_path = '.'.join([__package__, 'api', model_class.__api__])
+                api_module = sys.modules.get(api_path)
+                if api_module is None:
+                    api_module = utils.import_module(api_path)
+                top_api.set_value(model_class.__api__, api_module.get())
 
     def _init_tables(self, model_list):
         tables = []
 
         for model in model_list:
-            model_path = '.'.join([__package__, 'models', model])
-            module = utils.import_module(model_path)
-            tables.append(module.__table__)
+            model_class = getattr(models, model)
+            tables.append(model_class.__table__)
 
         tables_to_create = []
         for table in reversed(models.Base.metadata.sorted_tables):
diff --git a/keystone/common/bufferedhttp.py b/keystone/common/bufferedhttp.py
index 2c93ad7d..c6e3c2ec 100644
--- a/keystone/common/bufferedhttp.py
+++ b/keystone/common/bufferedhttp.py
@@ -36,6 +36,8 @@ from eventlet.green.httplib import CONTINUE, HTTPConnection, HTTPMessage, \
 
 DEFAULT_TIMEOUT = 30
 
+logger = logging.getLogger(__name__)
+
 
 # pylint: disable=R0902
 class BufferedHTTPResponse(HTTPResponse):
@@ -103,7 +105,7 @@ class BufferedHTTPConnection(HTTPConnection):
 
     def getresponse(self):
         response = HTTPConnection.getresponse(self)
-        logging.debug(("HTTP PERF: %(time).5f seconds to %(method)s "
+        logger.debug(("HTTP PERF: %(time).5f seconds to %(method)s "
                         "%(host)s:%(port)s %(path)s)"),
            {'time': time.time() - self._connected_time, 'method': self._method,
             'host': self.host, 'port': self.port, 'path': self._path})
diff --git a/keystone/contrib/extensions/__init__.py b/keystone/contrib/extensions/__init__.py
index 865efcb2..4d4d3b5c 100644
--- a/keystone/contrib/extensions/__init__.py
+++ b/keystone/contrib/extensions/__init__.py
@@ -16,31 +16,34 @@
 # See the License for the specific language governing permissions and
 # limitations under the License
 
-import ast
 import logging
+
 from keystone import utils
+
 EXTENSION_PREFIX = 'keystone.contrib.extensions.'
 DEFAULT_EXTENSIONS = 'osksadm,oskscatalog'
 CONFIG_EXTENSION_PROPERTY = 'extensions'
 
+logger = logging.getLogger(__name__)  # pylint: disable=C0103
+
 
 class BaseExtensionConfigurer(object):
-    def configure_extensions(self, extension_type,
-        mapper, options):
-        supported_extensions = options.get(
-            CONFIG_EXTENSION_PROPERTY, DEFAULT_EXTENSIONS)
+    def configure_extensions(self, extension_type, mapper, options):
+        supported_extensions = options.get(CONFIG_EXTENSION_PROPERTY,
+                                           DEFAULT_EXTENSIONS)
         for supported_extension in supported_extensions.split(','):
             self.extension_handlers = []
-            supported_extension = EXTENSION_PREFIX\
-            + extension_type + '.' + supported_extension.strip()\
-            + '.ExtensionHandler'
+            supported_extension = "%s%s.%s" % (
+                EXTENSION_PREFIX, extension_type, supported_extension.strip())
             try:
-                extenion_handler = utils.import_module(supported_extension)()
-                extenion_handler.map_extension_methods(mapper, options)
-                self.extension_handlers.append(extenion_handler)
+                extension_module = utils.import_module(supported_extension)
+                if hasattr(extension_module, 'ExtensionHandler'):
+                    extension_class = extension_module.ExtensionHandler()
+                    extension_class.map_extension_methods(mapper, options)
+                    self.extension_handlers.append(extension_class)
             except Exception as err:
-                logging.exception("Could not load extension for " +\
-                    extension_type + ':' + supported_extension + str(err))
+                logger.exception("Could not load extension for %s:%s %s" %
+                    (extension_type, supported_extension, err))
 
     def get_extension_handlers(self):
         return self.extension_handlers
diff --git a/keystone/controllers/token.py b/keystone/controllers/token.py
index 72263718..3524feb2 100644
--- a/keystone/controllers/token.py
+++ b/keystone/controllers/token.py
@@ -42,6 +42,8 @@ class TokenController(wsgi.Controller):
     def __init__(self, options):
         self.options = options
         self.identity_service = service.IdentityService(options)
+        logger.debug("Token controller init with HP-IDM extension: %s" % \
+                extension_reader.is_extension_supported(self.options, 'hpidm'))
 
     @utils.wrap_error
     def authenticate(self, req):
diff --git a/keystone/logic/service.py b/keystone/logic/service.py
index f19dc142..938e9300 100755
--- a/keystone/logic/service.py
+++ b/keystone/logic/service.py
@@ -1041,7 +1041,6 @@ class IdentityService(object):
     def remove_role_from_user(self, admin_token, user_id, role_id,
                               tenant_id=None):
         self.validate_service_admin_token(admin_token)
-        print user_id, role_id, tenant_id
         drolegrant = self.grant_manager.rolegrant_get_by_ids(user_id, role_id,
                                                                     tenant_id)
         if drolegrant is None:
diff --git a/keystone/test/__init__.py b/keystone/test/__init__.py
index 09be9966..50a30412 100644
--- a/keystone/test/__init__.py
+++ b/keystone/test/__init__.py
@@ -46,7 +46,6 @@
 """ Module that handles starting the Keystone server and running
 test suites"""
 
-import cgitb
 import heapq
 import logging
 from nose import config as noseconfig
@@ -58,7 +57,6 @@ import sys
 import tempfile
 import time
 import unittest
-cgitb.enable(format="text")
 
 import keystone
 import keystone.server
@@ -71,7 +69,7 @@ TEST_DIR = os.path.abspath(os.path.dirname(__file__))
 BASE_DIR = os.path.abspath(os.path.join(TEST_DIR, os.pardir, os.pardir))
 TEST_CERT = os.path.join(BASE_DIR, 'examples/ssl/certs/middleware-key.pem')
 
-logger = logging.getLogger('test')
+logger = logging.getLogger(__name__)
 
 
 class _AnsiColorizer(object):
@@ -370,7 +368,7 @@ class KeystoneTest(object):
                           os.path.join(TEST_DIR, fname)]
                 for fpath in paths:
                     if os.path.exists(fpath):
-                        print "Removing test file %s" % fname
+                        logger.debug("Removing test file %s" % fname)
                         os.unlink(fpath)
 
     def construct_temp_conf_file(self):
@@ -378,11 +376,17 @@ class KeystoneTest(object):
         template_fpath = os.path.join(TEST_DIR, 'etc', self.config_name)
         conf_contents = open(template_fpath).read()
         self.config_params['service_port'] = utils.get_unused_port()
+        logger.debug("Assigned port %s to service" %
+                     self.config_params['service_port'])
         self.config_params['admin_port'] = utils.get_unused_port()
+        logger.debug("Assigned port %s to admin" %
+                     self.config_params['admin_port'])
+
         conf_contents = conf_contents % self.config_params
         self.conf_fp = tempfile.NamedTemporaryFile()
         self.conf_fp.write(conf_contents)
         self.conf_fp.flush()
+        logger.debug("Create test configuration file: %s" % self.conf_fp.name)
         client_tests.TEST_CONFIG_FILE_NAME = self.conf_fp.name
 
     def setUp(self):
@@ -393,16 +397,23 @@ class KeystoneTest(object):
         self.server = None
         self.admin_server = None
 
-        self.clear_database()
         self.construct_temp_conf_file()
 
         # Set client certificate for test client
         if (self.isSsl == True):
+            logger.debug("SSL testing will use cert_file %s" % TEST_CERT)
             os.environ['cert_file'] = TEST_CERT
+        else:
+            if 'cert_file' in os.environ:
+                del os.environ['cert_file']
 
         # indicating HP-IDM is disabled
         if self.hpidmDisabled:
+            logger.debug("HP-IDM extensions is disabled")
             os.environ['HP-IDM_Disabled'] = 'True'
+        else:
+            if 'HP-IDM_Disabled' in os.environ:
+                del os.environ['HP-IDM_Disabled']
 
         # run the keystone server
         logger.info("Starting the keystone server...")
@@ -436,7 +447,8 @@ class KeystoneTest(object):
             client_tests.TEST_TARGET_SERVER_SERVICE_PORT = service.port
 
         except RuntimeError, e:
-            sys.exit("ERROR: %s" % e)
+            logger.exception(e)
+            raise e
 
         try:
             # Load Admin API server
@@ -456,8 +468,8 @@ class KeystoneTest(object):
             client_tests.TEST_TARGET_SERVER_ADMIN_PORT = admin.port
 
         except RuntimeError, e:
-            service.stop()
-            sys.exit("ERROR: %s" % e)
+            logger.exception(e)
+            raise e
 
         self.server = service
         self.admin_server = admin
@@ -482,36 +494,41 @@ class KeystoneTest(object):
             manage.process(*cmd)
 
     def tearDown(self):
-        # kill the keystone server
-        print "Stopping the keystone server..."
         try:
             if self.server is not None:
+                print "Stopping the Service API..."
                 self.server.stop()
                 self.server = None
             if self.admin_server is not None:
+                print "Stopping the Admin API..."
                 self.admin_server.stop()
                 self.admin_server = None
             if self.conf_fp:
                 self.conf_fp.close()
                 self.conf_fp = None
         except Exception as e:
+            logger.exception(e)
             print "Error cleaning up %s" % e
+            raise e
         finally:
             self.clear_database()
+            if 'cert_file' in os.environ:
+                del os.environ['cert_file']
+            if 'HP-IDM_Disabled' in os.environ:
+                del os.environ['HP-IDM_Disabled']
+            reload(client_tests)
 
     def run(self, args=None):
         try:
+            print 'Running test suite: %s' % self.__class__.__name__
+
             self.setUp()
 
             # discover and run tests
-            # TODO(zns): check if we still need a verbosity flag
-            verbosity = 1
-            if '--verbose' in sys.argv:
-                verbosity = 2
 
             # If any argument looks like a test name but doesn't have
-            # "nova.tests" in front of it, automatically add that so we don't
-            # have to type as much
+            # "keystone.test" in front of it, automatically add that so we
+            # don't have to type as much
             show_elapsed = True
             argv = []
             if args is None:
@@ -523,10 +540,6 @@ class KeystoneTest(object):
                     has_base = True
                 elif x.startswith('--hide-elapsed'):
                     show_elapsed = False
-                elif x.startswith('--trace-calls'):
-                    pass
-                elif x.startswith('--debug'):
-                    pass
                 elif x.startswith('-'):
                     argv.append(x)
                 else:
@@ -536,20 +549,26 @@ class KeystoneTest(object):
 
             if not has_base and self.directory_base is not None:
                 argv.append(self.directory_base)
+            argv = ['--no-path-adjustment'] + argv[1:]
+            logger.debug("Running set of tests with args=%s" % argv)
 
             c = noseconfig.Config(stream=sys.stdout,
                               env=os.environ,
                               verbosity=3,
                               workingDir=TEST_DIR,
-                              plugins=core.DefaultPluginManager())
+                              plugins=core.DefaultPluginManager(),
+                              args=argv)
 
             runner = NovaTestRunner(stream=c.stream,
                                     verbosity=c.verbosity,
                                     config=c,
                                     show_elapsed=show_elapsed)
 
-            return not core.run(config=c, testRunner=runner,
-                                argv=argv + ['--no-path-adjustment'])
+            result = not core.run(config=c, testRunner=runner, argv=argv)
+            return int(result)  # convert to values applicable to sys.exit()
+        except Exception, exc:
+            logger.exception(exc)
+            raise exc
         finally:
             self.tearDown()
 
@@ -573,14 +592,11 @@ class UnitTests(KeystoneTest):
         scoped_to_unit = False
         for x in sys.argv:
             if x.startswith(('functional', 'client')):
-                pass
+                # Skip, since we're not running unit tests
+                return
             elif x.startswith('unit'):
                 argv.append('keystone.test.%s' % x)
                 scoped_to_unit = True
-            elif x.startswith('--trace-calls'):
-                pass
-            elif x.startswith('--debug'):
-                pass
             else:
                 argv.append(x)
 
@@ -610,14 +626,11 @@ class ClientTests(KeystoneTest):
         scoped_to_client = False
         for x in sys.argv:
             if x.startswith(('functional', 'unit')):
-                pass
+                # Skip, since we're not running client tests
+                return
             elif x.startswith('client'):
                 argv.append('keystone.test.%s' % x)
                 scoped_to_client = True
-            elif x.startswith('--trace-calls'):
-                pass
-            elif x.startswith('--debug'):
-                pass
             else:
                 argv.append(x)
 
@@ -635,6 +648,29 @@ class SQLTest(KeystoneTest):
     test_files = ('keystone.sqltest.db',)
     directory_base = 'functional'
 
+    def run(self):
+        """ Run client tests
+
+        Filters arguments and leaves only ones relevant to client tests
+        """
+
+        argv = []
+        scoped_to_functional = False
+        for x in sys.argv:
+            if x.startswith(('client', 'unit')):
+                # Skip, since we're not running functional tests
+                return
+            elif x.startswith('functional'):
+                argv.append('keystone.test.%s' % x)
+                scoped_to_functional = True
+            else:
+                argv.append(x)
+
+        if not scoped_to_functional:
+            argv.append('keystone.test.functional')
+
+        return super(SQLTest, self).run(args=argv)
+
     def clear_database(self):
         # Disconnect the database before deleting
         from keystone.backends import sqlalchemy
diff --git a/keystone/test/etc/ldap.conf.template b/keystone/test/etc/ldap.conf.template
index feb73ecd..385afc93 100644
--- a/keystone/test/etc/ldap.conf.template
+++ b/keystone/test/etc/ldap.conf.template
@@ -2,7 +2,7 @@
 verbose = False
 debug = False
 default_store = sqlite
-log_file = %(test_dir)s/keystone.ldap.log
+log_file = %(test_dir)s/keystone.log
 log_dir = %(test_dir)s
 backends = keystone.backends.sqlalchemy,keystone.backends.ldap
 extensions= osksadm, oskscatalog, hpidm
diff --git a/keystone/test/etc/memcache.conf.template b/keystone/test/etc/memcache.conf.template
index 41bbb0b6..6cb434ac 100644
--- a/keystone/test/etc/memcache.conf.template
+++ b/keystone/test/etc/memcache.conf.template
@@ -2,7 +2,7 @@
 verbose = False
 debug = False
 default_store = sqlite
-log_file = %(test_dir)s/keystone.memcache.log
+log_file = %(test_dir)s/keystone.log
 log_dir = %(test_dir)s
 backends = keystone.backends.sqlalchemy,keystone.backends.memcache
 extensions= osksadm, oskscatalog, hpidm
diff --git a/keystone/test/etc/sql.conf.template b/keystone/test/etc/sql.conf.template
index d1aec939..c8b7b4b0 100644
--- a/keystone/test/etc/sql.conf.template
+++ b/keystone/test/etc/sql.conf.template
@@ -2,7 +2,7 @@
 verbose = False
 debug = False
 default_store = sqlite
-log_file = %(test_dir)s/keystone.sql.log
+log_file = %(test_dir)s/keystone.log
 log_dir = %(test_dir)s
 backends = keystone.backends.sqlalchemy
 extensions= osksadm, oskscatalog, hpidm
diff --git a/keystone/test/etc/sql_no_hpidm.conf.template b/keystone/test/etc/sql_no_hpidm.conf.template
index fde2eb44..c2c0b235 100644
--- a/keystone/test/etc/sql_no_hpidm.conf.template
+++ b/keystone/test/etc/sql_no_hpidm.conf.template
@@ -2,7 +2,7 @@
 verbose = False
 debug = False
 default_store = sqlite
-log_file = %(test_dir)s/keystone.sql.log
+log_file = %(test_dir)s/keystone.log
 log_dir = %(test_dir)s
 backends = keystone.backends.sqlalchemy
 extensions= osksadm, oskscatalog
diff --git a/keystone/test/etc/ssl.conf.template b/keystone/test/etc/ssl.conf.template
index 1f401975..1889c7d6 100644
--- a/keystone/test/etc/ssl.conf.template
+++ b/keystone/test/etc/ssl.conf.template
@@ -2,7 +2,7 @@
 verbose = False
 debug = False
 default_store = sqlite
-log_file = %(test_dir)s/keystone.ssl.log
+log_file = %(test_dir)s/keystone.log
 log_dir = %(test_dir)s
 backends = keystone.backends.sqlalchemy
 extensions= osksadm, oskscatalog, hpidm
diff --git a/keystone/test/functional/common.py b/keystone/test/functional/common.py
index 16b2e17e..798064b9 100644
--- a/keystone/test/functional/common.py
+++ b/keystone/test/functional/common.py
@@ -433,11 +433,13 @@ class ApiTestCase(RestfulTestCase):
         if self.use_server:
             path = ApiTestCase._version_path(version, path)
             if port is None:
-                port = client_tests.TEST_TARGET_SERVER_SERVICE_PORT
+                port = client_tests.TEST_TARGET_SERVER_SERVICE_PORT or 5000
             if host is None:
-                host = client_tests.TEST_TARGET_SERVER_SERVICE_ADDRESS
+                host = (client_tests.TEST_TARGET_SERVER_SERVICE_ADDRESS
+                            or '127.0.0.1')
             if protocol is None:
-                protocol = client_tests.TEST_TARGET_SERVER_SERVICE_PROTOCOL
+                protocol = (client_tests.TEST_TARGET_SERVER_SERVICE_PROTOCOL
+                            or 'http')
 
         if 'use_token' in kwargs:
             headers['X-Auth-Token'] = kwargs.pop('use_token')
@@ -459,11 +461,13 @@ class ApiTestCase(RestfulTestCase):
         if self.use_server:
             path = ApiTestCase._version_path(version, path)
             if port is None:
-                port = client_tests.TEST_TARGET_SERVER_ADMIN_PORT
+                port = client_tests.TEST_TARGET_SERVER_ADMIN_PORT or 35357
             if host is None:
-                host = client_tests.TEST_TARGET_SERVER_ADMIN_ADDRESS
+                host = (client_tests.TEST_TARGET_SERVER_ADMIN_ADDRESS
+                                or '127.0.0.1')
             if protocol is None:
-                protocol = client_tests.TEST_TARGET_SERVER_ADMIN_PROTOCOL
+                protocol = (client_tests.TEST_TARGET_SERVER_ADMIN_PROTOCOL
+                                or 'http')
 
         if 'use_token' in kwargs:
             headers['X-Auth-Token'] = kwargs.pop('use_token')
@@ -1589,6 +1593,9 @@ class MiddlewareTestCase(FunctionalTestCase):
     @unittest.skipIf(isSsl() or 'HP-IDM_Disabled' in os.environ,
                      "Skipping SSL or HP-IDM tests")
     def test_with_service_id(self):
+        if isSsl() or ('HP-IDM_Disabled' in os.environ):
+            # TODO(zns): why is this not skipping with the decorator?!
+            raise unittest.SkipTest("Skipping SSL or HP-IDM tests")
         # create a service role so the scope token validation will succeed
         role_resp = self.create_role(service_name=self.services[0]['name'])
         role = role_resp.json['role']
diff --git a/keystone/test/unit/test_migrations.py b/keystone/test/unit/test_migrations.py
index 044f15c2..a6fb5047 100644
--- a/keystone/test/unit/test_migrations.py
+++ b/keystone/test/unit/test_migrations.py
@@ -114,7 +114,6 @@ class TestMigrations(unittest.TestCase):
                           migration_api.db_version,
                           options)
         # Place the database under version control
-        print options
         print migration_api.version_control(options)
 
         cur_version = migration_api.db_version(options)
diff --git a/keystone/tools/tracer.py b/keystone/tools/tracer.py
index 7e9380fd..c5f0b53a 100644
--- a/keystone/tools/tracer.py
+++ b/keystone/tools/tracer.py
@@ -26,88 +26,134 @@
 OpenStack Call Tracing Tool
 
 To use this:
-1. include the tools dirextory in your project (__init__.py and tracer.py)
+1. include the tools directory in your project (__init__.py and tracer.py)
 2. import tools.tracer as early as possible into your module
-3. add --trace-calls to any argument parsers you use so the argument doesn't
-get flagged as invalid.
+3. add --trace-calls or -t to any argument parsers if you want the argument
+to be shown in the usage page
 
 Usage:
-# Add this as early as possible in the first module called in your service
-import tools.tracer   #load this first
+Add this as early as possible in the first module called in your service::
 
-If a '--trace-calls' parameter is found, it will trace calls to the console and
-space them to show the call graph.
+    import tools.tracer  # @UnusedImport # module runs on import
+
+If a '-t' or '--trace-calls' parameter is found, it will trace calls to stdout
+and space them to show the call graph. Exceptions (errors) will be displayed in
+red.
 
 """
 
+import linecache
 import os
 import sys
 
 
-if '--trace-calls' in sys.argv:
+if '--trace-calls' in sys.argv or '-t' in sys.argv:
+    # Pop the trace arguments
+    for i in range(len(sys.argv) - 1):
+        if sys.argv[i] in ['-t', '--trace-calls']:
+            sys.argv.pop(i)
+
     STACK_DEPTH = 0
 
+    # Calculate root project path
+    POSSIBLE_TOPDIR = os.path.normpath(os.path.join(
+                                       os.path.abspath(sys.argv[0]),
+                                       os.pardir,
+                                       os.pardir))
+
+    class ConsoleColors():
+        HEADER = '\033[95m'
+        OKBLUE = '\033[94m'
+        OKGREEN = '\033[92m'
+        WARNING = '\033[93m'
+        FAIL = '\033[91m'
+        ENDC = '\033[0m'
+
     def localtrace(frame, event, arg):
-        global STACK_DEPTH  # pylint: disable=W0603
         if event == "return":
+            global STACK_DEPTH  # pylint: disable=W0603
             STACK_DEPTH = STACK_DEPTH - 1
         elif event == "exception":
-            co = frame.f_code
-            func_name = co.co_name
-            line_no = frame.f_lineno
-            exc_type, exc_value, exc_traceback = arg  # pylint: disable=W0612
-            print '\033[91m%sERROR: %s %s on line %s of %s\033[0m' % \
-                ('  ' * STACK_DEPTH, exc_type.__name__, exc_value, line_no,
-                 func_name)
+            output_exception(frame, arg)
         return None
 
     def selectivetrace(frame, event, arg):  # pylint: disable=R0911
         global STACK_DEPTH  # pylint: disable=W0603
         if event == "exception":
+            output_exception(frame, arg)
+        if event == 'call':
             co = frame.f_code
             func_name = co.co_name
-            line_no = frame.f_lineno
-            exc_type, exc_value, exc_traceback = arg  # pylint: disable=W0612
-            print '\033[91m%sERROR: %s %s on line %s of %s\033[0m' % \
-                ('  ' * STACK_DEPTH, exc_type.__name__, exc_value, line_no,
-                 func_name)
-        if event != 'call':
+            if func_name == 'write':
+                # Ignore write() calls from print statements
+                return
+            func_filename = co.co_filename
+            if func_filename == "<string>":
+                return
+            if func_filename.startswith(("/System", "/Library",
+                                         "/usr/lib/py")):
+                return
+            if 'python' in func_filename:
+                return
+            if 'macosx' in func_filename:
+                return
+            output_call(frame, arg)
+            global STACK_DEPTH  # pylint: disable=W0603
+            STACK_DEPTH = STACK_DEPTH + 1
+            return localtrace
+        return
+
+    def output_exception(frame, arg):
+        exc_type, exc_value, exc_traceback = arg  # pylint: disable=W0612
+        if exc_type is StopIteration:
             return
+        global STACK_DEPTH  # pylint: disable=W0603
+        global POSSIBLE_TOPDIR  # pylint: disable=W0603
         co = frame.f_code
+        local_vars = frame.f_locals
         func_name = co.co_name
-        if func_name == 'write':
-            # Ignore write() calls from print statements
-            return
+        line_no = frame.f_lineno
         func_filename = co.co_filename
-        if func_filename == "<string>":
-            return
-        if func_filename.startswith("/System"):
-            return
-        if func_filename.startswith("/Library"):
-            return
-        if func_filename.startswith("/usr/lib/py"):
-            return
-        if 'macosx' in func_filename:
-            return
-        func_line_no = frame.f_lineno
-        # Calculate root project path
-        possible_topdir = os.path.normpath(os.path.join(
-                                           os.path.abspath(sys.argv[0]),
-                                           os.pardir,
-                                           os.pardir))
-        func_filename = func_filename.replace(possible_topdir, '')
+        func_filename = func_filename.replace(POSSIBLE_TOPDIR, '')
+        sys.stdout.write('%s%sERROR: %s %s in %s of %s:%s%s\n'
+                              % (ConsoleColors.FAIL, '  ' * STACK_DEPTH,
+                                 exc_type.__name__, exc_value, func_name,
+                                 func_filename, line_no, ConsoleColors.ENDC))
+        filename = co.co_filename
+        if filename == "<stdin>":
+            filename = "%s.py" % __file__
+        if (filename.endswith(".pyc") or
+            filename.endswith(".pyo")):
+            filename = filename[:-1]
+        line = linecache.getline(filename, line_no)
+        name = frame.f_globals["__name__"]
+        sys.stdout.write('%s%s    %s:%s: %s%s\n' %
+                         (ConsoleColors.HEADER, '  ' * STACK_DEPTH, name,
+                          line_no, line.rstrip(), ConsoleColors.ENDC))
+
+        sys.stdout.write('%s    locals: %s\n'
+                              % ('  ' * STACK_DEPTH,
+                                 local_vars))
+
+    def output_call(frame, arg):
         caller = frame.f_back
 
         if caller:
+            global STACK_DEPTH  # pylint: disable=W0603
+            global POSSIBLE_TOPDIR  # pylint: disable=W0603
+            co = frame.f_code
+            func_name = co.co_name
+            func_line_no = frame.f_lineno
+            func_filename = co.co_filename
+            func_filename = func_filename.replace(POSSIBLE_TOPDIR, '')
             caller_line_no = caller.f_lineno
             caller_filename = caller.f_code.co_filename.replace(
-                                                        possible_topdir, '')
-            print '%s%s::%s:%s      (from %s:%s)' % \
+                                                        POSSIBLE_TOPDIR, '')
+            if caller_filename == func_filename:
+                caller_filename = 'line'
+            sys.stdout.write('%s%s::%s:%s      (from %s:%s)\n' %
                 ('  ' * STACK_DEPTH, func_filename, func_name, func_line_no,
-                 caller_filename, caller_line_no)
-
-        STACK_DEPTH = STACK_DEPTH + 1
-        return localtrace
+                 caller_filename, caller_line_no))
 
+    sys.stdout.write('Starting OpenStack call tracer\n')
     sys.settrace(selectivetrace)
-    print 'Starting OpenStack call tracer'
diff --git a/keystone/utils.py b/keystone/utils.py
index c7e26a9a..0e7ce3ba 100755
--- a/keystone/utils.py
+++ b/keystone/utils.py
@@ -157,7 +157,8 @@ def import_module(module_name, class_name=None):
     be the last part of the module_name string.'''
     if class_name is None:
         try:
-            __import__(module_name)
+            if module_name not in sys.modules:
+                __import__(module_name)
             return sys.modules[module_name]
         except ImportError as exc:
             logging.exception(exc)
@@ -165,7 +166,8 @@ def import_module(module_name, class_name=None):
             if not exc.args[0].startswith('No module named %s' % class_name):
                 raise
     try:
-        __import__(module_name)
+        if module_name not in sys.modules:
+            __import__(module_name)
         return getattr(sys.modules[module_name], class_name)
     except (ImportError, ValueError, AttributeError), exception:
         logging.exception(exception)
diff --git a/run_tests.py b/run_tests.py
index 2c67e3e5..3168b4b8 100755
--- a/run_tests.py
+++ b/run_tests.py
@@ -12,19 +12,22 @@ To run a single test module:
     python run_tests.py functional.test_extensions
 
 """
+import logging
+import os
 import sys
 import subprocess
 
 import keystone.tools.tracer  # @UnusedImport # module runs on import
 from keystone import test
 
+logger = logging.getLogger(__name__)
 
 TESTS = [
     test.UnitTests,
     test.ClientTests,
+    test.SQLTest,
     test.SSLTest,
     test.ClientWithoutHPIDMTest,
-    test.SQLTest,
     test.LDAPTest,
     # Waiting on instructions on how to start memcached in jenkins:
     # But tests pass
@@ -32,39 +35,75 @@ TESTS = [
 ]
 
 
-if __name__ == '__main__':
-    if '-O' in sys.argv:
-        filter = None
+def parse_suite_filter():
+    """ Parses out -O or --only argument and returns the value after it as the
+    filter. Removes it from sys.argv in the process. """
+
+    filter = None
+    if '-O' in sys.argv or '--only' in sys.argv:
         for i in range(len(sys.argv)):
-            if sys.argv[i] == '-O':
+            if sys.argv[i] in ['-O', '--only']:
                 if len(sys.argv) > i + 1:
-                    filter = sys.argv[i + 1]
-                    # Remove -O settings from sys.argv
-                    argv = sys.argv[0:i]
-                    if len(sys.argv) > i:
-                        argv += sys.argv[i + 2:]
-                    sys.argv = argv[:]
+                    # Remove -O/--only settings from sys.argv
+                    sys.argv.pop(i)
+                    filter = sys.argv.pop(i)
                     break
-        if filter:
-            TESTS = [t for t in TESTS if filter in str(t)]
-            if not TESTS:
-                print 'No test configuration by the name %s found' % filter
-                exit()
+    return filter
+
 
+if __name__ == '__main__':
+    filter = parse_suite_filter()
+    if filter:
+        TESTS = [t for t in TESTS if filter in str(t)]
+        if not TESTS:
+            print 'No test configuration by the name %s found' % filter
+            exit()
     #Run test suites
     if len(TESTS) > 1:
-        # We have a problem with resetting SQLAlchemy, so we need to fire
-        # off a separate process for each test now
         for test_num, test_cls in enumerate(TESTS):
-            params = ["python", __file__, '-O',
-                      str(test_cls.__name__)] + sys.argv[1:]
-            p = subprocess.Popen(params)
-            result = p.wait()
-            if result:
-                sys.exit(result)
+            # We've had problems with resetting SQLAlchemy, so we can fire off
+            # a separate process for each test suite to guarantee the
+            # backend is clean. This is enabled with this constant.
+            run_separate_processes = False
+            if run_separate_processes:
+                params = ["python", __file__, '-O',
+                          str(test_cls.__name__)] + sys.argv[1:]
+                p = subprocess.Popen(params)
+                result = p.wait()
+                if result:
+                    sys.exit(result)
+            else:
+                try:
+                    result = test_cls().run()
+                    if result:
+                        logger.error("Run returned %s for test %s. Exiting" %
+                                     (result, test_cls.__name__))
+                        sys.exit(result)
+                except Exception, e:
+                    print "Error:", e
+                    logger.exception(e)
+                    sys.exit(2)
+            # Collect coverage from each run. They'll be combined later in .sh
+            if '--with-coverage' in sys.argv:
+                coverage_file = '.coverage.%s' % test_num
+                try:
+                    if os.path.exists(coverage_file):
+                        os.unlink(coverage_file)
+                    os.rename('.coverage', coverage_file)
+                except Exception, e:
+                    logger.exception(e)
+                    print "Failed to move .coverage file to %s: %s" % \
+                        (coverage_file, e)
 
     else:
         for test_num, test_cls in enumerate(TESTS):
-            print 'Running test suite: %s' % test_cls.__name__
-            if test_cls().run():
-                exit(1)
+            try:
+                result = test_cls().run()
+                if result:
+                    logger.error("Run returned %s for test %s. Exiting" %
+                                 result, test_cls.__name__)
+                    sys.exit(result)
+            except Exception, e:
+                print "Error:", e
+                logger.exception(e)
+                sys.exit(2)
diff --git a/run_tests.sh b/run_tests.sh
index 9905459f..7cabba57 100755
--- a/run_tests.sh
+++ b/run_tests.sh
@@ -6,7 +6,7 @@ function usage {
   echo "Usage: $0 [OPTION]..."
   echo "Run Keystone's test suite(s)"
   echo ""
-  echo "  -O test_name             Only run the specified test suite. Valid values are:"
+  echo "  -O, --only test_suite    Only run the specified test suite. Valid values are:"
   echo "                               UnitTests:    runs unit tests"
   echo "                               ClientTests:  runs tests that start and hit an HTTP[S] server"
   echo "                               SQLTest:      runs functional tests with SQLAlchemy backend"
@@ -47,7 +47,7 @@ function process_option {
       -h|--help) usage;;
       -V|--virtual-env) always_venv=1; never_venv=0;;
       -N|--no-virtual-env) always_venv=0; never_venv=1;;
-      -O) only_run_flag=1;;
+      -O|--only) only_run_flag=1;;
       -f|--force) force=1;;
       -p|--pep8) just_pep8=1;;
       -l|--pylint) just_pylint=1;;
@@ -183,8 +183,10 @@ fi
 
 run_tests
 
+# Since we run multiple test suites, we need to execute 'coverage combine'
 if [ $coverage -eq 1 ]; then
     echo "Generating coverage report in covhtml/"
+    ${wrapper} coverage combine
     ${wrapper} coverage html -d covhtml -i
 fi