Merge "Add logging when filtering returns nothing"

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",
+                    LOG.info(_LI("Filter %s returned 0 hosts"), cls_name)
-                              {'cls_name': cls_name})
+                    full_filter_results.append((cls_name, None))
-                    return
+                    list_objs = None
-                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)
                     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

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)