Merge "Check logs in some cinder and nova helper tests"

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

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)
 
 

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):

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'.

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()

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))