From 7d90a079b06a5367704cf696259b08cf192024c9 Mon Sep 17 00:00:00 2001 From: jgilaber Date: Thu, 8 May 2025 15:46:40 +0200 Subject: [PATCH] Check logs in some cinder and nova helper tests Check the debug logs for some methods in the cinder and nova helpers to reproduce the erros described in bug [1]. The logger is disabled by default, so the error was being ignored, in order to show the error, the logger needs to be enabled for the tests in question. The logging was disabled by allembic configuring logging in [2], so this patch also removes that logging config to expose the errors. [1] https://bugs.launchpad.net/watcher/+bug/2110149. [2] https://github.com/openstack/watcher/blob/master/watcher/db/sqlalchemy/alembic/env.py#L26 Change-Id: I3598ca1d08d260602c392f8a8098821faa53f570 --- watcher/db/sqlalchemy/alembic/env.py | 6 - watcher/tests/base.py | 8 +- watcher/tests/common/test_cinder_helper.py | 45 +++++-- watcher/tests/common/test_nova_helper.py | 10 +- watcher/tests/common/test_placement_helper.py | 9 +- watcher/tests/fixtures/__init__.py | 0 watcher/tests/fixtures/watcher.py | 115 ++++++++++++++++++ 7 files changed, 171 insertions(+), 22 deletions(-) create mode 100644 watcher/tests/fixtures/__init__.py create mode 100644 watcher/tests/fixtures/watcher.py 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))