openstack
/
cinder
Code Issues Proposed changes

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
This commit is contained in:
Pranali Deore 2016-04-13 04:59:47 -04:00 committed by PranaliD
parent c99ac09a8c
commit 7a1742c668
2 changed files with 91 additions and 9 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

57
cinder/scheduler/base_filter.py
View File

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

43
cinder/tests/unit/scheduler/test_base_filter.py
View File

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