Merge "Add fixture to limit unit test log output"

glance/tests/unit/fixtures.py

@@ -14,11 +14,105 @@
 # NOTE(mriedem): This is needed for importing from fixtures.
 from __future__ import absolute_import
 
+import logging as std_logging
+import os
 import warnings
 
 import fixtures as pyfixtures
 
 
+_TRUE_VALUES = ('True', 'true', '1', 'yes')
+
+
+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(pyfixtures.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.DEBUG)
+
+        # 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(
+            pyfixtures.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(
+                pyfixtures.LogHandler(handler, nuke_handlers=False))
+            handler.setLevel(std_logging.DEBUG)
+
+        # Don't log every single DB migration step
+        std_logging.getLogger(
+            'alembic.runtime.migration').setLevel(std_logging.WARNING)
+
+        # 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(
+            pyfixtures.MonkeyPatch('oslo_log.log.setup', fake_logging_setup))
+
+
 class WarningsFixture(pyfixtures.Fixture):
     """Filters out warnings during test runs."""
 

glance/tests/utils.py

@@ -27,6 +27,7 @@ from alembic import command as alembic_command
 import fixtures
 from oslo_config import cfg
 from oslo_config import fixture as cfg_fixture
+from oslo_log.fixture import logging_error as log_fixture
 from oslo_log import log
 from oslo_serialization import jsonutils
 from oslotest import moxstubout
@@ -87,6 +88,10 @@ class BaseTestCase(testtools.TestCase):
         # Limit the amount of DeprecationWarning messages in the unit test logs
         self.useFixture(glance_fixtures.WarningsFixture())
 
+        # Make sure logging output is limited but still test debug formatting
+        self.useFixture(log_fixture.get_logging_handle_error_fixture())
+        self.useFixture(glance_fixtures.StandardLogging())
+
     def set_policy(self):
         conf_file = "policy.json"
         self.policy_file = self._copy_data_file(conf_file, self.conf_dir)