From 7a1742c6689b4f3bda9cee90ecbb1691dde5c9e8 Mon Sep 17 00:00:00 2001 From: Pranali Deore Date: Wed, 13 Apr 2016 04:59:47 -0400 Subject: [PATCH] Add logging when filtering returns nothing When hosts are filtered for a request, and no host passes all the filters, operators can only see the last filter run; they have no visibility into which filter removed which host. This attempts to improve this situation by tracking the hosts remaining after each filter is run and the number of hosts removed. If no host is left, that information along with volume ID of the request would be logged. Since that can be a lot of information, it will call LOG.info with just the counts for all but the final filter, which will contain the last deleted host names, LOG.debug will output the full record of each filter and the hosts remaining after each step. This will better enable operators to determine why a particular host was not selected. Change-Id: I3baf75a4a4430c55b30dde1cae86fa5e195ec6d3 --- cinder/scheduler/base_filter.py | 57 ++++++++++++++++--- .../tests/unit/scheduler/test_base_filter.py | 43 ++++++++++++++ 2 files changed, 91 insertions(+), 9 deletions(-) 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)