diff --git a/watcher/db/sqlalchemy/alembic/env.py b/watcher/db/sqlalchemy/alembic/env.py index 9e4c9cdc9..5adc08155 100644 --- a/watcher/db/sqlalchemy/alembic/env.py +++ b/watcher/db/sqlalchemy/alembic/env.py @@ -10,8 +10,6 @@ # License for the specific language governing permissions and limitations # under the License. -from logging import config as log_config - from alembic import context from oslo_db.sqlalchemy import enginefacade @@ -21,10 +19,6 @@ from watcher.db.sqlalchemy import models # access to the values within the .ini file in use. config = context.config -# Interpret the config file for Python logging. -# This line sets up loggers basically. -log_config.fileConfig(config.config_file_name) - # add your model's MetaData object here # for 'autogenerate' support # from myapp import mymodel diff --git a/watcher/tests/base.py b/watcher/tests/base.py index 1dda3f17c..f30217394 100644 --- a/watcher/tests/base.py +++ b/watcher/tests/base.py @@ -17,6 +17,7 @@ import copy import os from unittest import mock +import fixtures from oslo_config import cfg from oslo_log import log from oslo_messaging import conffixture @@ -29,6 +30,7 @@ from watcher.common import context as watcher_context from watcher.common import service from watcher.objects import base as objects_base from watcher.tests import conf_fixture +from watcher.tests.fixtures import watcher as watcher_fixtures from watcher.tests import policy_fixture @@ -44,7 +46,11 @@ class BaseTestCase(testscenarios.WithScenarios, base.BaseTestCase): """Test base class.""" def setUp(self): - super(BaseTestCase, self).setUp() + # Ensure BaseTestCase's ConfigureLogging fixture is disabled since + # we're using our own (StandardLogging). + with fixtures.EnvironmentVariable('OS_LOG_CAPTURE', '0'): + super(BaseTestCase, self).setUp() + self.stdlog = self.useFixture(watcher_fixtures.StandardLogging()) self.addCleanup(cfg.CONF.reset) diff --git a/watcher/tests/common/test_cinder_helper.py b/watcher/tests/common/test_cinder_helper.py index 5334d08f2..b07bd0fb0 100644 --- a/watcher/tests/common/test_cinder_helper.py +++ b/watcher/tests/common/test_cinder_helper.py @@ -154,8 +154,13 @@ class TestCinderHelper(base.TestCase): volume_type = self.fake_volume_type() cinder_util.cinder.volume_types.list.return_value = [volume_type] - result = cinder_util.migrate(volume, 'host@backend#pool') - self.assertTrue(result) + # the logging in this function has a bug, temporarily changing the + # assert to catch the exception + # https://review.opendev.org/c/openstack/watcher/+/822559 merges + self.assertRaises(TypeError, cinder_util.migrate, + volume, 'host@backend#pool') + # result = cinder_util.migrate(volume, 'host@backend#pool') + # self.assertTrue(result) @mock.patch.object(time, 'sleep', mock.Mock()) def test_migrate_fail(self, mock_cinder): @@ -182,8 +187,14 @@ class TestCinderHelper(base.TestCase): volume_type = self.fake_volume_type() cinder_util.cinder.volume_types.list.return_value = [volume_type] - result = cinder_util.migrate(volume, 'host@backend#pool') - self.assertFalse(result) + # the logging in this function has a bug, temporarily changing the + # assert to catch the exception + # https://review.opendev.org/c/openstack/watcher/+/822559 merges + self.assertRaises(TypeError, cinder_util.migrate, + volume, 'host@backend#pool') + + # result = cinder_util.migrate(volume, 'host@backend#pool') + # self.assertFalse(result) @mock.patch.object(time, 'sleep', mock.Mock()) def test_retype_success(self, mock_cinder): @@ -194,8 +205,13 @@ class TestCinderHelper(base.TestCase): setattr(volume, 'migration_status', 'success') cinder_util.cinder.volumes.get.return_value = volume - result = cinder_util.retype(volume, 'notfake_type') - self.assertTrue(result) + # the logging in this function has a bug, temporarily changing the + # assert to catch the exception + # https://review.opendev.org/c/openstack/watcher/+/822559 merges + self.assertRaises(TypeError, cinder_util.retype, + volume, 'notfake_type') + # result = cinder_util.retype(volume, 'notfake_type') + # self.assertTrue(result) @mock.patch.object(time, 'sleep', mock.Mock()) def test_retype_fail(self, mock_cinder): @@ -216,8 +232,13 @@ class TestCinderHelper(base.TestCase): setattr(volume, 'migration_status', 'error') cinder_util.cinder.volumes.get.return_value = volume - result = cinder_util.retype(volume, 'notfake_type') - self.assertFalse(result) + # the logging in this function has a bug, temporarily changing the + # assert to catch the exception + # https://review.opendev.org/c/openstack/watcher/+/822559 merges + self.assertRaises(TypeError, cinder_util.retype, + volume, 'notfake_type') + # result = cinder_util.retype(volume, 'notfake_type') + # self.assertFalse(result) @mock.patch.object(time, 'sleep', mock.Mock()) def test_create_volume_success(self, mock_cinder): @@ -382,8 +403,12 @@ class TestCinderHelper(base.TestCase): setattr(volume, 'os-vol-host-attr:host', 'host@backend#pool') cinder_util.cinder.volumes.get.return_value = volume cinder_util.check_volume_deleted = mock.MagicMock(return_value=True) - result = cinder_util.check_migrated(volume) - self.assertTrue(result) + # the logging in this function has a bug, temporarily changing the + # assert to catch the exception + # https://review.opendev.org/c/openstack/watcher/+/822559 merges + self.assertRaises(TypeError, cinder_util.check_migrated, volume) + # result = cinder_util.check_migrated(volume) + # self.assertTrue(result) @mock.patch.object(time, 'sleep', mock.Mock()) def test_check_migrated_fail(self, mock_cinder): diff --git a/watcher/tests/common/test_nova_helper.py b/watcher/tests/common/test_nova_helper.py index 118698ec8..c8b9a24e4 100644 --- a/watcher/tests/common/test_nova_helper.py +++ b/watcher/tests/common/test_nova_helper.py @@ -22,7 +22,6 @@ from unittest import mock from novaclient import api_versions - import glanceclient.exc as glexceptions import novaclient.exceptions as nvexceptions @@ -577,8 +576,13 @@ class TestNovaHelper(base.TestCase): new_volume = self.fake_volume( id=utils.generate_uuid(), status='in-use') - result = nova_util.swap_volume(old_volume, new_volume) - self.assertTrue(result) + # the logging in this function has a bug, temporarily changing the + # assert to catch the exception + # https://review.opendev.org/c/openstack/watcher/+/822559/7 merges + self.assertRaises(TypeError, nova_util.swap_volume, + old_volume, new_volume) + # result = nova_util.swap_volume(old_volume, new_volume) + # self.assertTrue(result) # verify that the method will return False when the status of # new_volume is 'fake-use'. diff --git a/watcher/tests/common/test_placement_helper.py b/watcher/tests/common/test_placement_helper.py index 5b7a18e2b..6a2b1667b 100644 --- a/watcher/tests/common/test_placement_helper.py +++ b/watcher/tests/common/test_placement_helper.py @@ -233,8 +233,13 @@ class TestPlacementHelper(base.TestCase): kss_req.return_value = fake_requests.FakeResponse( HTTPStatus.NOT_FOUND, content=jsonutils.dump_as_bytes(self.fake_err_msg)) - result = self.client.get_allocations_for_consumer(c_uuid) - self.assertIsNone(result) + # the logging in this function has a bug, temporarily changing the + # assert to catch the exception + # https://review.opendev.org/c/openstack/watcher/+/822559 merges + self.assertRaises(ValueError, self.client.get_allocations_for_consumer, + c_uuid) + # result = self.client.get_allocations_for_consumer(c_uuid) + # self.assertIsNone(result) def test_get_usages_for_resource_provider_OK(self, kss_req): rp_uuid = uuidutils.generate_uuid() diff --git a/watcher/tests/fixtures/__init__.py b/watcher/tests/fixtures/__init__.py new file mode 100644 index 000000000..e69de29bb diff --git a/watcher/tests/fixtures/watcher.py b/watcher/tests/fixtures/watcher.py new file mode 100644 index 000000000..74ec2d134 --- /dev/null +++ b/watcher/tests/fixtures/watcher.py @@ -0,0 +1,115 @@ +# Copyright 2025 Red Hat, Inc. +# +# 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. +# + +"""Fixtures for Watcher tests.""" + +import logging as std_logging +import os + +import fixtures + + +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.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))