Merge "Add 'StandardLogging' fixture"

keystone/tests/unit/core.py

@@ -677,6 +677,7 @@ class BaseTestCase(testtools.TestCase):
         self.useFixture(fixtures.MockPatchObject(sys, 'exit',
                                                  side_effect=UnexpectedExit))
         self.useFixture(log_fixture.get_logging_handle_error_fixture())
+        self.stdlog = self.useFixture(ksfixtures.StandardLogging())
         self.useFixture(ksfixtures.WarningsFixture())
 
         # Ensure we have an empty threadlocal context at the start of each

keystone/tests/unit/ksfixtures/__init__.py

@@ -16,5 +16,6 @@ from keystone.tests.unit.ksfixtures.backendloader import BackendLoader  # noqa
 from keystone.tests.unit.ksfixtures.cache import Cache  # noqa
 from keystone.tests.unit.ksfixtures.jws_key_repository import JWSKeyRepository  # noqa
 from keystone.tests.unit.ksfixtures.key_repository import KeyRepository  # noqa
+from keystone.tests.unit.ksfixtures.logging import StandardLogging  # noqa
 from keystone.tests.unit.ksfixtures.policy import Policy  # noqa
 from keystone.tests.unit.ksfixtures.warnings import WarningsFixture  # noqa

keystone/tests/unit/ksfixtures/logging.py

@@ -0,0 +1,114 @@
+# Licensed under the Apache License, Version 2.0 (the "License"); you may
+# not use this file except in compliance with the License. You may obtain
+# a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+# WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+# License for the specific language governing permissions and limitations
+# under the License.
+
+import logging as std_logging
+import os
+
+import fixtures
+
+
+class NullHandler(std_logging.Handler):
+    """Custom default NullHandler to attempt to format the record.
+
+    Used 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 NullLogger 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().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', 'true', '1', 'yes'):
+            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)
+
+            # Don't log every single DB migration step
+            std_logging.getLogger(
+                'migrate.versioning.api').setLevel(std_logging.WARNING)
+            # Or alembic for model comparisons.
+            std_logging.getLogger('alembic').setLevel(std_logging.WARNING)
+            # Or oslo_db provisioning steps
+            std_logging.getLogger('oslo_db.sqlalchemy').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 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))
+
+    def delete_stored_logs(self):
+        # NOTE(gibi): this depends on the internals of the fixtures.FakeLogger.
+        # This could be enhanced once the PR
+        # https://github.com/testing-cabal/fixtures/pull/42 is released
+        self.logger._output.truncate(0)

keystone/tests/unit/ksfixtures/warnings.py

@@ -42,6 +42,14 @@ class WarningsFixture(fixtures.Fixture):
             message=r"Using function/method 'db_version\(\)' is deprecated",
         )
 
+        # TODO(stephenfin): Remove these when we drop support for
+        # sqlalchemy-migrate
+        warnings.filterwarnings(
+            'ignore',
+            category=sqla_exc.SADeprecationWarning,
+            module='migrate.versioning',
+        )
+
         # TODO(stephenfin): We should filter on the specific RemovedIn20Warning
         # warnings that affect us, so that we can slowly start addressing them
         warnings.simplefilter('error', sqla_exc.SAWarning)

keystone/tests/unit/test_sql_upgrade.py

@@ -11,6 +11,7 @@
 # WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
 # License for the specific language governing permissions and limitations
 # under the License.
+
 """
 Test for SQL migration extensions.
 
@@ -25,12 +26,12 @@ To run these tests against a live database:
 
 3. Run the tests using::
 
-    tox -e py27 -- keystone.tests.unit.test_sql_upgrade
+    tox -e py39 -- keystone.tests.unit.test_sql_upgrade
 
 For further information, see `oslo.db documentation
 <https://docs.openstack.org/oslo.db/latest/contributor/index.html#how-to-run-unit-tests>`_.
 
-WARNING::
+.. warning::
 
     Your database will be wiped.
 
@@ -51,6 +52,7 @@ from migrate.versioning import script
 from oslo_db import exception as db_exception
 from oslo_db.sqlalchemy import enginefacade
 from oslo_db.sqlalchemy import test_fixtures as db_fixtures
+from oslo_log import fixture as log_fixture
 from oslo_log import log
 from oslo_serialization import jsonutils
 from oslotest import base as test_base
@@ -264,6 +266,11 @@ class MigrateBase(
 ):
     def setUp(self):
         super().setUp()
+
+        self.useFixture(log_fixture.get_logging_handle_error_fixture())
+        self.stdlog = self.useFixture(ksfixtures.StandardLogging())
+        self.useFixture(ksfixtures.WarningsFixture())
+
         self.engine = enginefacade.writer.get_engine()
         self.sessionmaker = enginefacade.writer.get_sessionmaker()