diff --git a/cinder/scheduler/base_filter.py b/cinder/scheduler/base_filter.py index 92f1b5c0064..6f51b1475ca 100644 --- a/cinder/scheduler/base_filter.py +++ b/cinder/scheduler/base_filter.py @@ -17,6 +17,7 @@ Filter support """ from oslo_log import log as logging +import six from cinder.i18n import _LI from cinder.scheduler import base_handler @@ -63,6 +64,28 @@ class BaseFilterHandler(base_handler.BaseHandler): This class should be subclassed where one needs to use filters. """ + def _log_filtration(self, full_filter_results, + part_filter_results, filter_properties): + # Log the filtration history + rspec = filter_properties.get("request_spec", {}) + msg_dict = {"vol_id": rspec.get("volume_id", ""), + "str_results": six.text_type(full_filter_results), + } + full_msg = ("Filtering removed all hosts for the request with " + "volume ID " + "'%(vol_id)s'. Filter results: %(str_results)s" + ) % msg_dict + msg_dict["str_results"] = ', '.join( + _LI("%(cls_name)s: (start: %(start)s, end: %(end)s)") % { + "cls_name": value[0], "start": value[1], "end": value[2]} + for value in part_filter_results) + part_msg = _LI("Filtering removed all hosts for the request with " + "volume ID " + "'%(vol_id)s'. Filter results: %(str_results)s" + ) % msg_dict + LOG.debug(full_msg) + LOG.info(part_msg) + def get_filtered_objects(self, filter_classes, objs, filter_properties, index=0): """Get objects after filter @@ -77,21 +100,37 @@ class BaseFilterHandler(base_handler.BaseHandler): """ list_objs = list(objs) LOG.debug("Starting with %d host(s)", len(list_objs)) + # The 'part_filter_results' list just tracks the number of hosts + # before and after the filter, unless the filter returns zero + # hosts, in which it records the host/nodename for the last batch + # that was removed. Since the full_filter_results can be very large, + # it is only recorded if the LOG level is set to debug. + part_filter_results = [] + full_filter_results = [] for filter_cls in filter_classes: cls_name = filter_cls.__name__ + start_count = len(list_objs) filter_class = filter_cls() if filter_class.run_filter_for_index(index): objs = filter_class.filter_all(list_objs, filter_properties) if objs is None: - LOG.debug("Filter %(cls_name)s says to stop filtering", - {'cls_name': cls_name}) - return - list_objs = list(objs) - msg = (_LI("Filter %(cls_name)s returned %(obj_len)d host(s)") - % {'cls_name': cls_name, 'obj_len': len(list_objs)}) - if not list_objs: - LOG.info(msg) + LOG.info(_LI("Filter %s returned 0 hosts"), cls_name) + full_filter_results.append((cls_name, None)) + list_objs = None break - LOG.debug(msg) + + list_objs = list(objs) + end_count = len(list_objs) + part_filter_results.append((cls_name, start_count, end_count)) + remaining = [getattr(obj, "host", obj) + for obj in list_objs] + full_filter_results.append((cls_name, remaining)) + + LOG.debug("Filter %(cls_name)s returned " + "%(obj_len)d host(s)", + {'cls_name': cls_name, 'obj_len': len(list_objs)}) + if not list_objs: + self._log_filtration(full_filter_results, + part_filter_results, filter_properties) return list_objs diff --git a/cinder/tests/unit/scheduler/test_base_filter.py b/cinder/tests/unit/scheduler/test_base_filter.py index 7eae7e35400..28733f74dc0 100644 --- a/cinder/tests/unit/scheduler/test_base_filter.py +++ b/cinder/tests/unit/scheduler/test_base_filter.py @@ -17,7 +17,9 @@ import mock from oslotest import moxstubout from cinder.scheduler import base_filter +from cinder.scheduler import host_manager from cinder import test +from cinder.tests.unit import fake_constants as fake class TestBaseFilter(test.TestCase): @@ -95,6 +97,18 @@ class FakeFilter5(BaseFakeFilter): pass +class FilterA(base_filter.BaseFilter): + def filter_all(self, list_objs, filter_properties): + # return all but the first object + return list_objs[1:] + + +class FilterB(base_filter.BaseFilter): + def filter_all(self, list_objs, filter_properties): + # return an empty list + return None + + class FakeExtensionManager(list): def __init__(self, namespace): @@ -166,3 +180,32 @@ class TestBaseFilterHandler(test.TestCase): result = self._get_filtered_objects(filter_classes, index=2) self.assertEqual(filter_objs_expected, result) self.assertEqual(1, fake5_filter_all.call_count) + + def test_get_filtered_objects_info_and_debug_log_none_returned(self): + + all_filters = [FilterA, FilterA, FilterB] + fake_hosts = [host_manager.HostState('fake_host%s' % x) + for x in range(1, 4)] + + filt_props = {"request_spec": {'volume_id': fake.VOLUME_ID, + 'volume_properties': {'project_id': fake.PROJECT_ID, + 'size': 2048, + 'host': 'host4'}}} + with mock.patch.object(base_filter, 'LOG') as mock_log: + result = self.handler.get_filtered_objects( + all_filters, fake_hosts, filt_props) + self.assertFalse(result) + msg = "with volume ID '%s'" % fake.VOLUME_ID + # FilterA should leave Host1 and Host2; FilterB should leave None. + exp_output = ("FilterA: (start: 3, end: 2), " + "FilterA: (start: 2, end: 1)") + cargs = mock_log.info.call_args[0][0] + self.assertIn(msg, cargs) + self.assertIn(exp_output, cargs) + + exp_output = ("[('FilterA', ['fake_host2', 'fake_host3']), " + "('FilterA', ['fake_host3']), " + + "('FilterB', None)]") + cargs = mock_log.debug.call_args[0][0] + self.assertIn(msg, cargs) + self.assertIn(exp_output, cargs)