Merge "Mock logging during unit tests"

barbican/tests/api/middleware/test_context.py

@@ -14,12 +14,11 @@
 # limitations under the License.
 from unittest import mock
 
-import oslotest.base as oslotest
-
 from barbican.api.middleware import context
+from barbican.tests import utils
 
 
-class TestUnauthenticatedContextMiddleware(oslotest.BaseTestCase):
+class TestUnauthenticatedContextMiddleware(utils.BaseTestCase):
 
     def setUp(self):
         super(TestUnauthenticatedContextMiddleware, self).setUp()

barbican/tests/cmd/test_barbican_manage.py

@@ -30,8 +30,6 @@ class TestBarbicanManageBase(utils.BaseTestCase):
         clear_conf()
         self.addCleanup(clear_conf)
 
-        self.useFixture(fixtures.MonkeyPatch(
-            'oslo_log.log.setup', lambda barbican_test, version='test': None))
         manager.CONF.set_override('sql_connection', 'mockdburl')
 
     def _main_test_helper(self, argv, func_name=None, *exp_args, **exp_kwargs):

barbican/tests/database_utils.py

@@ -25,6 +25,7 @@ from sqlalchemy import event
 
 from barbican.model import models
 from barbican.model import repositories
+from barbican.tests import fixture as barbican_fixture
 
 
 @event.listens_for(Engine, "connect")
@@ -275,6 +276,7 @@ class RepositoryTestCase(oslotest.BaseTestCase):
     """
     def setUp(self):
         super(RepositoryTestCase, self).setUp()
+        self.useFixture(barbican_fixture.StandardLogging())
         setup_in_memory_db()
 
         # Clean up once tests are completed.

barbican/tests/fixture.py

@@ -10,6 +10,9 @@
 #  License for the specific language governing permissions and limitations
 #  under the License.
 
+import logging as std_logging
+import os
+
 import fixtures
 from oslo_db.sqlalchemy import session
 from oslo_utils import timeutils
@@ -18,6 +21,9 @@ import sqlalchemy as sa
 from barbican.model import models
 
 
+_TRUE_VALUES = ('True', 'true', '1', 'yes')
+
+
 class SessionQueryFixture(fixtures.Fixture):
     """Fixture for testing queries on a session
 
@@ -72,3 +78,87 @@ class SessionQueryFixture(fixtures.Fixture):
         s.updated_at = timeutils.parse_isotime(updated_at)
         s.project_id = project.id
         session.add(s)
+
+
+class NullHandler(std_logging.Handler):
+    """custom default NullHandler to attempt to format the record.
+
+    Used in conjunction with
+    log_fixture.get_logging_handle_error_fixture to detect formatting errors in
+    debug level logs without saving the logs.
+    """
+    def handle(self, record):
+        self.format(record)
+
+    def emit(self, record):
+        pass
+
+    def createLock(self):
+        self.lock = None
+
+
+class StandardLogging(fixtures.Fixture):
+    """Setup Logging redirection for tests.
+
+    There are a number of things we want to handle with logging in tests:
+
+    * Redirect the logging to somewhere that we can test or dump it later.
+
+    * Ensure that as many DEBUG messages as possible are actually
+       executed, to ensure they are actually syntactically valid (they
+       often have not been).
+
+    * Ensure that we create useful output for tests that doesn't
+      overwhelm the testing system (which means we can't capture the
+      100 MB of debug logging on every run).
+
+    To do this we create a logger fixture at the root level, which
+    defaults to INFO and create a Null Logger at DEBUG which lets
+    us execute log messages at DEBUG but not keep the output.
+
+    To support local debugging OS_DEBUG=True can be set in the
+    environment, which will print out the full debug logging.
+
+    There are also a set of overrides for particularly verbose
+    modules to be even less than INFO.
+
+    """
+
+    def setUp(self):
+        super(StandardLogging, self).setUp()
+
+        # set root logger to debug
+        root = std_logging.getLogger()
+        root.setLevel(std_logging.INFO)
+
+        # supports collecting debug level for local runs
+        if os.environ.get('OS_DEBUG') in _TRUE_VALUES:
+            level = std_logging.DEBUG
+        else:
+            level = std_logging.INFO
+
+        # Collect logs
+        fs = '%(asctime)s %(levelname)s [%(name)s] %(message)s'
+        self.logger = self.useFixture(
+            fixtures.FakeLogger(format=fs, level=None))
+        # TODO(sdague): why can't we send level through the fake
+        # logger? Tests prove that it breaks, but it's worth getting
+        # to the bottom of.
+        root.handlers[0].setLevel(level)
+
+        if level > std_logging.DEBUG:
+            # Just attempt to format debug level logs, but don't save them
+            handler = NullHandler()
+            self.useFixture(fixtures.LogHandler(handler, nuke_handlers=False))
+            handler.setLevel(std_logging.DEBUG)
+
+        # At times we end up calling back into main() functions in
+        # testing. This has the possibility of calling logging.setup
+        # again, which completely unwinds the logging capture we've
+        # created here. Once we've setup the logging in the way we want,
+        # disable the ability for the test to change this.
+        def fake_logging_setup(*args):
+            pass
+
+        self.useFixture(
+            fixtures.MonkeyPatch('oslo_log.log.setup', fake_logging_setup))

barbican/tests/queue/test_retry_scheduler.py

@@ -16,12 +16,13 @@ import time
 from unittest import mock
 
 import eventlet
-import oslotest.base as oslotest
 
 from barbican.model import models
 from barbican.model import repositories
 from barbican.queue import retry_scheduler
 from barbican.tests import database_utils
+from barbican.tests import utils
+
 
 # Oslo messaging RPC server uses eventlet.
 eventlet.monkey_patch()
@@ -148,7 +149,7 @@ class WhenRunningPeriodicServerRetryLogic(database_utils.RepositoryTestCase):
         return args, kwargs, retry_repo
 
 
-class WhenRunningPeriodicServer(oslotest.BaseTestCase):
+class WhenRunningPeriodicServer(utils.BaseTestCase):
     """Tests the timing-related functionality of the periodic task retry server.
 
     These tests are only concerned with whether or not periodic tasks are

barbican/tests/utils.py

@@ -38,6 +38,7 @@ from barbican.plugin.crypto import p11_crypto
 from barbican.plugin.interface import secret_store
 from barbican.plugin import kmip_secret_store as kss
 from barbican.tests import database_utils
+from barbican.tests import fixture as barbican_fixture
 
 
 def mock_pecan_request(test_instance, host=None, version='1.0'):
@@ -73,6 +74,7 @@ class BarbicanAPIBaseTestCase(oslotest.BaseTestCase):
 
     def setUp(self):
         super(BarbicanAPIBaseTestCase, self).setUp()
+        self.useFixture(barbican_fixture.StandardLogging())
         # Make sure we have a test db and session to work with
         database_utils.setup_in_memory_db()
 
@@ -96,9 +98,9 @@ class BarbicanAPIBaseTestCase(oslotest.BaseTestCase):
 
 
 class BaseTestCase(oslotest.BaseTestCase):
-    """DEPRECATED - Will remove in future refactoring."""
     def setUp(self):
         super(BaseTestCase, self).setUp()
+        self.useFixture(barbican_fixture.StandardLogging())
         self.order_id = 'order1234'
         self.external_project_id = 'keystone1234'
         self.request_id = 'request1234'