diff --git a/nova/filters.py b/nova/filters.py index 993102c9a676..7ac06b89da59 100644 --- a/nova/filters.py +++ b/nova/filters.py @@ -68,18 +68,57 @@ class BaseFilterHandler(loadables.BaseLoader): def get_filtered_objects(self, filters, objs, filter_properties, index=0): list_objs = list(objs) LOG.debug("Starting with %d host(s)", len(list_objs)) + # Track the hosts as they are removed. The 'full_filter_results' list + # contains the host/nodename info for every host that passes each + # filter, while the 'part_filter_results' list just tracks the number + # removed by each filter, unless the filter returns zero hosts, in + # which case 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 = [] + log_msg = "%(cls_name)s: (start: %(start)s, end: %(end)s)" for filter_ in filters: if filter_.run_filter_for_index(index): cls_name = filter_.__class__.__name__ + start_count = len(list_objs) objs = filter_.filter_all(list_objs, filter_properties) if objs is None: LOG.debug("Filter %s says to stop filtering", cls_name) return list_objs = list(objs) - if not list_objs: + end_count = len(list_objs) + part_filter_results.append(log_msg % {"cls_name": cls_name, + "start": start_count, "end": end_count}) + if list_objs: + remaining = [(getattr(obj, "host", obj), + getattr(obj, "nodename", "")) + for obj in list_objs] + full_filter_results.append((cls_name, remaining)) + else: LOG.info(_LI("Filter %s returned 0 hosts"), cls_name) + full_filter_results.append((cls_name, None)) break 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: + # Log the filtration history + rspec = filter_properties.get("request_spec", {}) + inst_props = rspec.get("instance_properties", {}) + msg_dict = {"res_id": inst_props.get("reservation_id", ""), + "inst_uuid": inst_props.get("uuid", ""), + "str_results": str(full_filter_results), + } + full_msg = ("Filtering removed all hosts for the request with " + "reservation ID '%(res_id)s' and instance ID " + "'%(inst_uuid)s'. Filter results: %(str_results)s" + ) % msg_dict + msg_dict["str_results"] = str(part_filter_results) + part_msg = _LI("Filtering removed all hosts for the request with " + "reservation ID '%(res_id)s' and instance ID " + "'%(inst_uuid)s'. Filter results: %(str_results)s" + ) % msg_dict + LOG.debug(full_msg) + LOG.info(part_msg) return list_objs diff --git a/nova/tests/unit/scheduler/test_filters.py b/nova/tests/unit/scheduler/test_filters.py index 1d713882c6f7..9950847562d2 100644 --- a/nova/tests/unit/scheduler/test_filters.py +++ b/nova/tests/unit/scheduler/test_filters.py @@ -18,6 +18,7 @@ Tests For Scheduler Host Filters. import inspect import sys +import mock from six.moves import range from nova import filters @@ -36,6 +37,13 @@ class Filter2(filters.BaseFilter): class FiltersTestCase(test.NoDBTestCase): + + def setUp(self): + super(FiltersTestCase, self).setUp() + with mock.patch.object(loadables.BaseLoader, "__init__") as mock_load: + mock_load.return_value = None + self.filter_handler = filters.BaseFilterHandler(filters.BaseFilter) + def test_filter_all(self): filter_obj_list = ['obj1', 'obj2', 'obj3'] filter_properties = 'fake_filter_properties' @@ -201,3 +209,71 @@ class FiltersTestCase(test.NoDBTestCase): filter_objs_initial, filter_properties) self.assertIsNone(result) + + def test_get_filtered_objects_info_log_none_returned(self): + LOG = filters.LOG + + class FilterA(filters.BaseFilter): + def filter_all(self, list_objs, filter_properties): + # return all but the first object + return list_objs[1:] + + class FilterB(filters.BaseFilter): + def filter_all(self, list_objs, filter_properties): + # return an empty list + return [] + + filter_a = FilterA() + filter_b = FilterB() + all_filters = [filter_a, filter_b] + hosts = ["Host0", "Host1", "Host2"] + fake_res_id = "reservation" + fake_uuid = "uuid" + filt_props = {"request_spec": {"instance_properties": { + "reservation_id": fake_res_id, + "uuid": fake_uuid}}} + with mock.patch.object(LOG, "info") as mock_log: + result = self.filter_handler.get_filtered_objects( + all_filters, hosts, filt_props) + self.assertFalse(result) + # FilterA should leave Host1 and Host2; FilterB should leave None. + exp_output = ("['FilterA: (start: 3, end: 2)', " + "'FilterB: (start: 2, end: 0)']") + cargs = mock_log.call_args[0][0] + self.assertIn("with reservation ID '%s'" % fake_res_id, cargs) + self.assertIn("and instance ID '%s'" % fake_uuid, cargs) + self.assertIn(exp_output, cargs) + + def test_get_filtered_objects_debug_log_none_returned(self): + LOG = filters.LOG + + class FilterA(filters.BaseFilter): + def filter_all(self, list_objs, filter_properties): + # return all but the first object + return list_objs[1:] + + class FilterB(filters.BaseFilter): + def filter_all(self, list_objs, filter_properties): + # return an empty list + return [] + + filter_a = FilterA() + filter_b = FilterB() + all_filters = [filter_a, filter_b] + hosts = ["Host0", "Host1", "Host2"] + fake_res_id = "reservation" + fake_uuid = "uuid" + filt_props = {"request_spec": {"instance_properties": { + "reservation_id": fake_res_id, + "uuid": fake_uuid}}} + with mock.patch.object(LOG, "debug") as mock_log: + result = self.filter_handler.get_filtered_objects( + all_filters, hosts, filt_props) + self.assertFalse(result) + # FilterA should leave Host1 and Host2; FilterB should leave None. + exp_output = ("[('FilterA', [('Host1', ''), ('Host2', '')]), " + + "('FilterB', None)]") + cargs = mock_log.call_args[0][0] + self.assertIn("with reservation ID '%s'" % fake_res_id, cargs) + self.assertIn("and instance ID '%s'" % fake_uuid, cargs) + self.assertIn(exp_output, cargs)