From 36f2ee58d517c945d13cb8caa6bd01ee0c1450a3 Mon Sep 17 00:00:00 2001 From: Stephen Finucane Date: Thu, 6 Jan 2022 17:53:08 +0000 Subject: [PATCH] Add 'StandardLogging' fixture Another fixture taken wholesale from nova. This configures our logging to ensure we trigger but don't capture DEBUG-level logs. It also lowers the level of some less important logs like sqlalchemy-migrate. Change-Id: Ia1090f1810d6cddda724a8a048647b4ffeaa733e Signed-off-by: Stephen Finucane --- keystone/tests/unit/core.py | 1 + keystone/tests/unit/ksfixtures/__init__.py | 1 + keystone/tests/unit/ksfixtures/logging.py | 114 +++++++++++++++++++++ keystone/tests/unit/ksfixtures/warnings.py | 8 ++ keystone/tests/unit/test_sql_upgrade.py | 11 +- 5 files changed, 133 insertions(+), 2 deletions(-) create mode 100644 keystone/tests/unit/ksfixtures/logging.py diff --git a/keystone/tests/unit/core.py b/keystone/tests/unit/core.py index 3e873dbbaa..c8b71cff38 100644 --- a/keystone/tests/unit/core.py +++ b/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 diff --git a/keystone/tests/unit/ksfixtures/__init__.py b/keystone/tests/unit/ksfixtures/__init__.py index a76e5e5a9c..a5fedbfc83 100644 --- a/keystone/tests/unit/ksfixtures/__init__.py +++ b/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 diff --git a/keystone/tests/unit/ksfixtures/logging.py b/keystone/tests/unit/ksfixtures/logging.py new file mode 100644 index 0000000000..419880deb4 --- /dev/null +++ b/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) diff --git a/keystone/tests/unit/ksfixtures/warnings.py b/keystone/tests/unit/ksfixtures/warnings.py index 11d69567c8..9e3a9c4d47 100644 --- a/keystone/tests/unit/ksfixtures/warnings.py +++ b/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) diff --git a/keystone/tests/unit/test_sql_upgrade.py b/keystone/tests/unit/test_sql_upgrade.py index fd038105e4..c7a8b7e2be 100644 --- a/keystone/tests/unit/test_sql_upgrade.py +++ b/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 `_. -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()