From 2e1de319e8fa6e5307eaf3b95b64068263b6a4f2 Mon Sep 17 00:00:00 2001 From: Takashi Kajinami Date: Sat, 7 Aug 2021 23:39:56 +0900 Subject: [PATCH] Mock logging during unit tests ... to avoid huge number of IOError during tests. The BaseTestCase class is un-deprecated because the class is still widely used and is considered to be a good place to implement that common mocking. Note this implementation is based on the one in cinder. Story: 2009097 Task: 42939 Change-Id: I1a25a4575ba4c03ab66f8a8768b9e92c517088fa --- barbican/tests/api/middleware/test_context.py | 5 +- barbican/tests/cmd/test_barbican_manage.py | 2 - barbican/tests/database_utils.py | 2 + barbican/tests/fixture.py | 90 +++++++++++++++++++ barbican/tests/queue/test_retry_scheduler.py | 5 +- barbican/tests/utils.py | 4 +- 6 files changed, 100 insertions(+), 8 deletions(-) diff --git a/barbican/tests/api/middleware/test_context.py b/barbican/tests/api/middleware/test_context.py index ea8aba326..3838d152f 100644 --- a/barbican/tests/api/middleware/test_context.py +++ b/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() diff --git a/barbican/tests/cmd/test_barbican_manage.py b/barbican/tests/cmd/test_barbican_manage.py index 46aec891d..e4803be82 100644 --- a/barbican/tests/cmd/test_barbican_manage.py +++ b/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): diff --git a/barbican/tests/database_utils.py b/barbican/tests/database_utils.py index 248a3c36c..1dd1af4a5 100644 --- a/barbican/tests/database_utils.py +++ b/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. diff --git a/barbican/tests/fixture.py b/barbican/tests/fixture.py index aec7e1580..cea582782 100644 --- a/barbican/tests/fixture.py +++ b/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)) diff --git a/barbican/tests/queue/test_retry_scheduler.py b/barbican/tests/queue/test_retry_scheduler.py index 1a9f6c6c4..5abf8fe04 100644 --- a/barbican/tests/queue/test_retry_scheduler.py +++ b/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 diff --git a/barbican/tests/utils.py b/barbican/tests/utils.py index c8e891829..a4cd99dc0 100644 --- a/barbican/tests/utils.py +++ b/barbican/tests/utils.py @@ -39,6 +39,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'): @@ -74,6 +75,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() @@ -97,9 +99,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'